Mailing List Archive

I've been looking at this some more, and it seems the problem is the
same as it was before. The PURGE does not seem to work immediately. The
restarted request gets a HIT, then the next request gets a MISS and
after that the HITs start again. Here's a sequence from varnishlog showing:

- the PURGE,
- the restart,
- the MISS,
- the HIT

Again this is a full output for everything in the log on that URL. Names
and IP addresses have been changed.

Thanks
Nigel

* << Request >> 266604
- Begin req 266603 rxreq
- Timestamp Start: 1495662133.465511 0.000000 0.000000
- Timestamp Req: 1495662133.465511 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx2 57250
- ReqMethod PURGE
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader TE: deflate,gzip;q=0.3
- ReqHeader Connection: TE, close
- ReqHeader Accept-Encoding: gzip
- ReqHeader Host: www.example.com
- ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx2
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_acl MATCH purgers "xxx.xxx.xxx.xx2"
- VCL_return purge
- VCL_call HASH
- VCL_return lookup
- VCL_call PURGE
- ReqMethod GET
- VCL_return restart
- Timestamp Restart: 1495662133.465563 0.000052 0.000052
- Link req 266605 restart
- End

* << Request >> 266605
- Begin req 266604 restart
- Timestamp Start: 1495662133.465563 0.000052 0.000000
- ReqStart xxx.xxx.xxx.xx2 57250
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader TE: deflate,gzip;q=0.3
- ReqHeader Connection: TE, close
- ReqHeader Accept-Encoding: gzip
- ReqHeader Host: www.example.com
- ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx2
- ReqHeader X-Processed-By: Melian
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 132102
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 02:37:14 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 02:37:15 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 266605 132102
- RespHeader Age: 68698
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 68698
- RespHeader Age: 0
- RespHeader X-Cache: HIT (7)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 266605 132102
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495662133.465618 0.000107 0.000055
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 7493
- Debug "RES_MODE 2"
- RespHeader Connection: close
- Timestamp Resp: 1495662133.465660 0.000149 0.000042
- ReqAcct 225 0 225 396 7493 7889
- End

* << Request >> 3017
- Begin req 3016 rxreq
- Timestamp Start: 1495664394.000921 0.000000 0.000000
- Timestamp Req: 1495664394.000921 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx3 45771
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: Keep-alive
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader From: googlebot(at)googlebot.com
- ReqHeader User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1;
+http://www.google.com/bot.html)
- ReqHeader Accept-Encoding: gzip,deflate,br
- ReqHeader If-Modified-Since: Wed, 24 May 2017 15:16:04 GMT
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx3
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_return hash
- ReqUnset Accept-Encoding: gzip,deflate,br
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 3018 fetch
- Timestamp Fetch: 1495664394.381188 0.380267 0.380267
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 3017
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Cache: MISS
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 3017
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495664394.381214 0.380294 0.000026
- RespHeader Accept-Ranges: bytes
- RespHeader Transfer-Encoding: chunked
- Debug "RES_MODE 8"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495664394.396562 0.395641 0.015347
- ReqAcct 409 0 409 404 7493 7897
- End

* << Request >> 35821
- Begin req 35820 rxreq
- Timestamp Start: 1495668065.207785 0.000000 0.000000
- Timestamp Req: 1495668065.207785 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx1 33904
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: Keep-alive
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader From: googlebot(at)googlebot.com
- ReqHeader User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1;
+http://www.google.com/bot.html)
- ReqHeader Accept-Encoding: gzip,deflate,br
- ReqHeader If-Modified-Since: Wed, 24 May 2017 22:19:54 GMT
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx1
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_return hash
- ReqUnset Accept-Encoding: gzip,deflate,br
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- Hit 3018
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 35821 3018
- RespHeader Age: 3670
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 3670
- RespHeader Age: 0
- RespHeader X-Cache: HIT (1)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 35821 3018
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495668065.207927 0.000142 0.000142
- RespProtocol HTTP/1.1
- RespStatus 304
- RespReason Not Modified
- RespReason Not Modified
- Debug "RES_MODE 0"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495668065.208002 0.000217 0.000075
- ReqAcct 409 0 409 367 0 367
- End

On 23/05/2017 17:58, Nigel Peck wrote:
>
> Hi,
>
> I have an issue where some requests are not getting served from the
> cache when they should be. "should be" as in it's my intention they
> should be, and not sure what's going wrong to cause them not to be. I
> had some discussion about this issue before, when I was on 4.0.4, and
> the suggestion was to upgrade, which I've now done and am on 4.1.6.
>
> Below is a full varnishlog report for an image URL. My VCL sets a week
> TTL on every backend response that is going to be stored, and is then
> kept up to date with PURGEs from a script when needed or every four days
> otherwise, so everything that can be cached should be coming out of the
> cache at all times. The first two entries below are the PURGE/restart
> and then the subsequent entry a MISS. There are no other entries, this
> is a complete report from:
>
> sudo varnishlog -d -q 'ReqURL eq "/example/image/URI/image.jpg"'
>
> Names have been changed to protect the guilty. Nothing has been
> lru_nuked at all, there is no entry for it in varnishstat.
>
> There is an "Age" header on the restarted response after the purge,
> which seems strange. I can't see a "TTL" record on the restarted
> response either.
>
> All insights greatly appreciated. Please let me know if any further info
> needed.
>
> Nigel
>
> --
>
> * << Request >> 230779
> - Begin req 230778 rxreq
> - Timestamp Start: 1495505749.920337 0.000000 0.000000
> - Timestamp Req: 1495505749.920337 0.000000 0.000000
> - ReqStart 192.168.0.1 33530
> - ReqMethod PURGE
> - ReqURL /example/image/URI/image.jpg
> - ReqProtocol HTTP/1.1
> - ReqHeader TE: deflate,gzip;q=0.3
> - ReqHeader Connection: TE, close
> - ReqHeader Accept-Encoding: gzip
> - ReqHeader Host: www.example.com
> - ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
> - ReqHeader X-Forwarded-For: 192.168.0.1
> - VCL_call RECV
> - ReqHeader X-Processed-By: Melian
> - VCL_acl MATCH purgers "192.168.0.1"
> - VCL_return purge
> - VCL_call HASH
> - VCL_return lookup
> - VCL_call PURGE
> - ReqMethod GET
> - VCL_return restart
> - Timestamp Restart: 1495505749.920445 0.000108 0.000108
> - Link req 230780 restart
> - End
>
> * << Request >> 230780
> - Begin req 230779 restart
> - Timestamp Start: 1495505749.920445 0.000108 0.000000
> - ReqStart 192.168.0.1 33530
> - ReqMethod GET
> - ReqURL /example/image/URI/image.jpg
> - ReqProtocol HTTP/1.1
> - ReqHeader TE: deflate,gzip;q=0.3
> - ReqHeader Connection: TE, close
> - ReqHeader Accept-Encoding: gzip
> - ReqHeader Host: www.example.com
> - ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
> - ReqHeader X-Forwarded-For: 192.168.0.1
> - ReqHeader X-Processed-By: Melian
> - VCL_call RECV
> - VCL_return hash
> - VCL_call HASH
> - VCL_return lookup
> - Hit 168785
> - VCL_call HIT
> - VCL_return deliver
> - RespProtocol HTTP/1.1
> - RespStatus 200
> - RespReason OK
> - RespHeader Date: Mon, 22 May 2017 18:41:37 GMT
> - RespHeader Server: Apache/2
> - RespHeader Last-Modified: Thu, 02 Mar 2017 02:22:25 GMT
> - RespHeader ETag: "1e40-549b6198b7a40"
> - RespHeader Content-Length: 7744
> - RespHeader Content-Type: image/jpeg
> - RespHeader X-Host: www.example.com
> - RespHeader X-URL: /example/image/URI/image.jpg
> - RespHeader Cache-Control: max-age=3600
> - RespHeader X-Varnish: 230780 168785
> - RespHeader Age: 27252
> - RespHeader Via: 1.1 varnish-v4
> - VCL_call DELIVER
> - RespUnset Age: 27252
> - RespHeader Age: 0
> - RespHeader X-Cache: HIT (1)
> - RespUnset X-Host: www.example.com
> - RespUnset X-URL: /example/image/URI/image.jpg
> - RespUnset X-Varnish: 230780 168785
> - RespUnset Via: 1.1 varnish-v4
> - RespHeader Via: Varnish
> - VCL_return deliver
> - Timestamp Process: 1495505749.920481 0.000144 0.000036
> - RespHeader Accept-Ranges: bytes
> - Debug "RES_MODE 2"
> - RespHeader Connection: close
> - Timestamp Resp: 1495505749.920542 0.000204 0.000060
> - ReqAcct 227 0 227 306 7744 8050
> - End
>
> * << Request >> 2031637
> - Begin req 131739 rxreq
> - Timestamp Start: 1495573815.866983 0.000000 0.000000
> - Timestamp Req: 1495573815.866983 0.000000 0.000000
> - ReqStart 86.153.27.10 48595
> - ReqMethod GET
> - ReqURL /example/image/URI/image.jpg
> - ReqProtocol HTTP/1.1
> - ReqHeader Host: www.example.com
> - ReqHeader Connection: keep-alive
> - ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 6.0.1;
> SAMSUNG SM-G900F Build/MMB29M) AppleWebKit/537.36 (KHTML, like Gecko)
> SamsungBrowser/5.4 Chrome/51.0.2704.106 Mobile Safari/537.36
> - ReqHeader Accept: image/webp,image/*,*/*;q=0.8
> - ReqHeader Referer: http://www.example.com/jcb-parts-catalogue
> - ReqHeader Accept-Encoding: gzip, deflate
> - ReqHeader Accept-Language: en-GB,en-US,en
> - ReqHeader Cookie: _gat=1;
> hgkjb432k5vb4k35vb4k35n32vbmn423=bjjb423jbr2bkj234bjk324bkj;
> PRODUCT_BROWSING_FEATURES_USED=1; _ga=GA1.2.1234567890.1234567890;
> _gid=GA1.2.1234567890.1234567890
> - ReqHeader X-Forwarded-For: 86.153.27.10
> - VCL_call RECV
> - ReqHeader X-Processed-By: Melian
> - ReqUnset Cookie: _gat=1;
> hgkjb432k5vb4k35vb4k35n32vbmn423=bjjb423jbr2bkj234bjk324bkj;
> PRODUCT_BROWSING_FEATURES_USED=1; _ga=GA1.2.1234567890.1234567890;
> _gid=GA1.2.1234567890.1234567890
> - VCL_return hash
> - ReqUnset Accept-Encoding: gzip, deflate
> - ReqHeader Accept-Encoding: gzip
> - VCL_call HASH
> - VCL_return lookup
> - VCL_call MISS
> - VCL_return fetch
> - Link bereq 2031638 fetch
> - Timestamp Fetch: 1495573815.869083 0.002100 0.002100
> - RespProtocol HTTP/1.1
> - RespStatus 200
> - RespReason OK
> - RespHeader Date: Tue, 23 May 2017 21:10:15 GMT
> - RespHeader Server: Apache/2
> - RespHeader Last-Modified: Thu, 02 Mar 2017 02:22:25 GMT
> - RespHeader ETag: "1e40-549b6198b7a40"
> - RespHeader Content-Length: 7744
> - RespHeader Content-Type: image/jpeg
> - RespHeader X-Host: www.example.com
> - RespHeader X-URL: /example/image/URI/image.jpg
> - RespHeader Cache-Control: max-age=3600
> - RespHeader X-Varnish: 2031637
> - RespHeader Age: 0
> - RespHeader Via: 1.1 varnish-v4
> - VCL_call DELIVER
> - RespUnset Age: 0
> - RespHeader Age: 0
> - RespHeader X-Cache: MISS
> - RespUnset X-Host: www.example.com
> - RespUnset X-URL: /example/image/URI/image.jpg
> - RespUnset X-Varnish: 2031637
> - RespUnset Via: 1.1 varnish-v4
> - RespHeader Via: Varnish
> - VCL_return deliver
> - Timestamp Process: 1495573815.869164 0.002180 0.000080
> - RespHeader Accept-Ranges: bytes
> - Debug "RES_MODE 2"
> - RespHeader Connection: keep-alive
> - Timestamp Resp: 1495573815.869250 0.002266 0.000086
> - ReqAcct 655 0 655 308 7744 8052
> - End
>
> --
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

How reliably can you reproduce? You you mind sharing your VCL (either
pastebin, or just to me)?

I searched the log for restarted purge requests that have received a
HIT, and there are quite a lot of them. Many are ok though, and get a
MISS. There are also entries that have this sequence:

- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 886033
- VCL_call HIT
- VCL_return miss
- VCL_Error vcl_hit{} returns miss without busy object. Doing pass.
- VCL_call PASS
- VCL_return fetch

I'm happy to share my VCL, and yes would prefer just to you at this
point. I could look at creating a cut-down version later to share on the
list if it's useful. I'll email that to you separately now.

Thanks for this.

Nigel

On 24/05/2017 19:25, Guillaume Quintard wrote:
> How reliably can you reproduce? You you mind sharing your VCL (either
> pastebin, or just to me)?

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Just a bit more info on this. I got some numbers for you.

MISS Restarted Requests
2433

HIT Restarted Requests
375

Got the error: vcl_hit{} returns miss without busy object
28

On 25/05/2017 12:34, Nigel Peck wrote:
>
> I searched the log for restarted purge requests that have received a
> HIT, and there are quite a lot of them. Many are ok though, and get a
> MISS. There are also entries that have this sequence:
>
> - VCL_call RECV
> - VCL_return hash
> - VCL_call HASH
> - VCL_return lookup
> - Hit 886033
> - VCL_call HIT
> - VCL_return miss
> - VCL_Error vcl_hit{} returns miss without busy object. Doing pass.
> - VCL_call PASS
> - VCL_return fetch
>
> I'm happy to share my VCL, and yes would prefer just to you at this
> point. I could look at creating a cut-down version later to share on the
> list if it's useful. I'll email that to you separately now.
>
> Thanks for this.
>
> Nigel
>
> On 24/05/2017 19:25, Guillaume Quintard wrote:
>> How reliably can you reproduce? You you mind sharing your VCL (either
>> pastebin, or just to me)?
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Hi,

Just in case this is useful, the 'vcl_hit{} returns miss without busy object' error is documented in https://github.com/varnishcache/varnish-cache/issues/1799 <https://github.com/varnishcache/varnish-cache/issues/1799>. It happens when obj.ttl + obj.grace > 0 and leaving 'vcl_hit' with 'return (miss)'. While the object is being re-fetched those errors will be logged because request coalescing won't work as expected for later requests of the same object. That means later requests will enter 'vcl_hit' and then will be handled as pass requests. Once the objet is re-fetched, further requests will behave as expected.

Best,

--
Carlos Abalde

Thanks Carlos, I did see that issue on GitHub and very helpful to have
the short version :) It seems that in some cases hits are being
attempted on objects that are in the process of being purged, or
something like that, which is causing this error.

Thanks,
Nigel

On 25/05/2017 14:25, Carlos Abalde wrote:
> Hi,
>
> Just in case this is useful, the 'vcl_hit{} returns miss without busy
> object' error is documented in
> https://github.com/varnishcache/varnish-cache/issues/1799. It happens
> when obj.ttl + obj.grace > 0 and leaving 'vcl_hit' with 'return (miss)'.
> While the object is being re-fetched those errors will be logged because
> request coalescing won't work as expected for later requests of the same
> object. That means later requests will enter 'vcl_hit' and then will be
> handled as pass requests. Once the objet is re-fetched, further requests
> will behave as expected.
>
> Best,
>
> --
> Carlos Abalde
>

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Just another update on this, regarding how reliably I can reproduce. I
have now updated my code for purging the cache, so it reports which
purged objects received a HIT when they were retrieved with the
restarted request after the purge, and it happens every time I purge a
significant number of items from the cache, perhaps 10% of them or
something like that. So I can reproduce reliably.

Thanks
Nigel

On 24/05/2017 19:25, Guillaume Quintard wrote:
> How reliably can you reproduce? You you mind sharing your VCL (either
> pastebin, or just to me)?

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

On Sat, May 27, 2017 at 9:30 PM, Nigel Peck <np.lists@sharphosting.uk> wrote:
>
> Just another update on this, regarding how reliably I can reproduce. I have
> now updated my code for purging the cache, so it reports which purged
> objects received a HIT when they were retrieved with the restarted request
> after the purge, and it happens every time I purge a significant number of
> items from the cache, perhaps 10% of them or something like that. So I can
> reproduce reliably.

Dunno how you define "which purged objects received a HIT" but I would
enable Hash records to be able to compare them in the logs to first
make sure they actually are the same.

See man varnishd, look for vsl_mask.

Dridi

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

On Tue, May 30, 2017 at 8:06 PM, Nigel Peck <np.lists@sharphosting.uk> wrote:
>
> Thanks, I'll look at that to make sure. The situation is, if I purge an
> object, and that request is restarted in vcl_purge, it is by definition the
> same object, is it not? Since it is the exact same request. So what I'm
> saying is, about 10% of requests that I purge, receive a HIT on the restart
> of that same request.
>
> It's not because of intervening requests and I've not made any changes to
> vcl_hash, so it's a very simple hash that isn't being changed before the
> restart in vcl_purge.

It is possible that while the purge is happening another client
requests the same object and once the purge restarts into a GET or HIT
it gets a hit from the other client's request.

Grouping logs (by session or request) might help better understand
what's happening. I haven't read this thread in details. Also please
keep the list in CC.

Cheers,
Dridi

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

On Wed, May 31, 2017 at 4:49 PM, Dridi Boukelmoune <dridi@varni.sh> wrote:
>
> It is possible that while the purge is happening another client
> requests the same object and once the purge restarts into a GET or HIT
> it gets a hit from the other client's request.
>

I got that idea too, but the HIT after the purge return an object with a
large age.

--
Guillaume Quintard

On 31/05/2017 09:49, Dridi Boukelmoune wrote:
> On Tue, May 30, 2017 at 8:06 PM, Nigel Peck <np.lists@sharphosting.uk> wrote:
>>
>> Thanks, I'll look at that to make sure. The situation is, if I purge an
>> object, and that request is restarted in vcl_purge, it is by definition the
>> same object, is it not? Since it is the exact same request. So what I'm
>> saying is, about 10% of requests that I purge, receive a HIT on the restart
>> of that same request.
>>
>> It's not because of intervening requests and I've not made any changes to
>> vcl_hash, so it's a very simple hash that isn't being changed before the
>> restart in vcl_purge.
>
> It is possible that while the purge is happening another client
> requests the same object and once the purge restarts into a GET or HIT
> it gets a hit from the other client's request.
>
> Grouping logs (by session or request) might help better understand
> what's happening. I haven't read this thread in details. Also please
> keep the list in CC.

Sorry about missing the list off the CC, was an oversight on my part,
must have hit the wrong button and missed that I did that.

It's not due to other requests happening between. As Guillaume says the
age is high, and also I checked many of these in varnishlog by looking
at all entries for the URL and there is never a request in between.

Perhaps a good next step would be for me to set up a minimal install on
a fresh CentOS 7 instance and see if I can reproduce there with minimal
VCL? Although there is nothing in the VCL I have that should cause this
intermittent behaviour.

Nigel

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

On Wed, May 31, 2017 at 6:25 PM, Guillaume Quintard
<guillaume@varnish-software.com> wrote:
>
>
> On Wed, May 31, 2017 at 4:49 PM, Dridi Boukelmoune <dridi@varni.sh> wrote:
>>
>> It is possible that while the purge is happening another client
>> requests the same object and once the purge restarts into a GET or HIT
>> it gets a hit from the other client's request.
>
>
> I got that idea too, but the HIT after the purge return an object with a
> large age.

The age is something that could come from the backend. Does the VXID
match the one that was just purged when a restart gets a hit?

Dridi

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

> Sorry about missing the list off the CC, was an oversight on my part, must
> have hit the wrong button and missed that I did that.

No worries, reading my previous email I must say that remark doesn't
look nice. I wrote it in a rush like I often do on this list.

> It's not due to other requests happening between. As Guillaume says the age
> is high, and also I checked many of these in varnishlog by looking at all
> entries for the URL and there is never a request in between.

There's no ordering guarantee in the varnishlog output, although they
should likely be ordered since they share the same hash. You'd need to
check the Timestamp records to get a grasp of chronology.

> Perhaps a good next step would be for me to set up a minimal install on a
> fresh CentOS 7 instance and see if I can reproduce there with minimal VCL?
> Although there is nothing in the VCL I have that should cause this
> intermittent behaviour.

If it's a bug, it might be one of those hard to reproduce...

Amazingly enough I never looked at the logs of a purge, maybe ExpKill
could give us a VXID to then check against the hit. If only SomeoneElse(tm)
could spare me the time and look at it themselves and tell us (wink wink=).

Cheers

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

On 31/05/2017 18:33, Dridi Boukelmoune wrote:
> There's no ordering guarantee in the varnishlog output, although they
> should likely be ordered since they share the same hash. You'd need to
> check the Timestamp records to get a grasp of chronology.

Thanks, I'll keep that in mind. I looked at a typical set of entries
that I saved. This is not a busy site. All the timestamps are in order.

I've included the full log below, based on a search for the ReqURL.
There is the PURGE and then the restart that gets a HIT. The restart
shows itself as being the 7th hit on that object - X-Cache: HIT (7) - I
can't check the VXID because the PURGE entry doesn't include it[1].

And then the next request, 40 minutes later, gets a MISS. All caching on
this server is for one week. The next request an hour after that gets
HIT(1). So all working properly apart from the restart getting a HIT,
resulting in the next request getting a MISS instead[2].

It seems clear to me that there is some bug causing a delay on the PURGE
going through in some cases (around 10% of purges in my case), so the
restart comes back round before the PURGE has completed. The purge
completes after the restart.

[1] - I'm not sure how I can get the VXID for a purge, since it seems
vcl_purge does not have access to the obj it is going to purge.
Hopefully the obj.hits being more than 1 or 2 in the restarted hit is
evidence enough, and the lack of intervening entries on this non-busy site.

[2] - Very noticeable in my case, because I am using Varnish to ensure
every request is a cache HIT, even for pages that only get viewed once
or twice a week, to improve performance. So I'm monitoring MISSes and
seeing this happening.

> If it's a bug, it might be one of those hard to reproduce...
>
> Amazingly enough I never looked at the logs of a purge, maybe ExpKill
> could give us a VXID to then check against the hit. If only SomeoneElse(tm)
> could spare me the time and look at it themselves and tell us (wink wink=).

I'm very happy to help in any way I can. Please let me know anything I
can do or information I can provide. I'm no C programmer (web
developer/server admin), so can't help out with
coding/patching/debugging[3], but anything else I can do, please let me
know what you need.

Would a cleanly installed server and absolute minimum VCL to reproduce
this be useful? You would be welcome to have access to that server, if
useful, once I've got it set up and producing the same problem.

Nigel

[3] - Assuming it's a bug, which for my part I'm convinced it is at this
point.

* << Request >> 266604
- Begin req 266603 rxreq
- Timestamp Start: 1495662133.465511 0.000000 0.000000
- Timestamp Req: 1495662133.465511 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx2 57250
- ReqMethod PURGE
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader TE: deflate,gzip;q=0.3
- ReqHeader Connection: TE, close
- ReqHeader Accept-Encoding: gzip
- ReqHeader Host: www.example.com
- ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx2
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_acl MATCH purgers "xxx.xxx.xxx.xx2"
- VCL_return purge
- VCL_call HASH
- VCL_return lookup
- VCL_call PURGE
- ReqMethod GET
- VCL_return restart
- Timestamp Restart: 1495662133.465563 0.000052 0.000052
- Link req 266605 restart
- End

* << Request >> 266605
- Begin req 266604 restart
- Timestamp Start: 1495662133.465563 0.000052 0.000000
- ReqStart xxx.xxx.xxx.xx2 57250
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader TE: deflate,gzip;q=0.3
- ReqHeader Connection: TE, close
- ReqHeader Accept-Encoding: gzip
- ReqHeader Host: www.example.com
- ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx2
- ReqHeader X-Processed-By: Melian
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 132102
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 02:37:14 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 02:37:15 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 266605 132102
- RespHeader Age: 68698
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 68698
- RespHeader Age: 0
- RespHeader X-Cache: HIT (7)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 266605 132102
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495662133.465618 0.000107 0.000055
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 7493
- Debug "RES_MODE 2"
- RespHeader Connection: close
- Timestamp Resp: 1495662133.465660 0.000149 0.000042
- ReqAcct 225 0 225 396 7493 7889
- End

* << Request >> 3017
- Begin req 3016 rxreq
- Timestamp Start: 1495664394.000921 0.000000 0.000000
- Timestamp Req: 1495664394.000921 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx3 45771
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: Keep-alive
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader From: googlebot(at)googlebot.com
- ReqHeader User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1;
+http://www.google.com/bot.html)
- ReqHeader Accept-Encoding: gzip,deflate,br
- ReqHeader If-Modified-Since: Wed, 24 May 2017 15:16:04 GMT
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx3
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_return hash
- ReqUnset Accept-Encoding: gzip,deflate,br
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 3018 fetch
- Timestamp Fetch: 1495664394.381188 0.380267 0.380267
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 3017
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Cache: MISS
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 3017
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495664394.381214 0.380294 0.000026
- RespHeader Accept-Ranges: bytes
- RespHeader Transfer-Encoding: chunked
- Debug "RES_MODE 8"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495664394.396562 0.395641 0.015347
- ReqAcct 409 0 409 404 7493 7897
- End

* << Request >> 35821
- Begin req 35820 rxreq
- Timestamp Start: 1495668065.207785 0.000000 0.000000
- Timestamp Req: 1495668065.207785 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx1 33904
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: Keep-alive
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader From: googlebot(at)googlebot.com
- ReqHeader User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1;
+http://www.google.com/bot.html)
- ReqHeader Accept-Encoding: gzip,deflate,br
- ReqHeader If-Modified-Since: Wed, 24 May 2017 22:19:54 GMT
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx1
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_return hash
- ReqUnset Accept-Encoding: gzip,deflate,br
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- Hit 3018
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 35821 3018
- RespHeader Age: 3670
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 3670
- RespHeader Age: 0
- RespHeader X-Cache: HIT (1)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 35821 3018
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495668065.207927 0.000142 0.000142
- RespProtocol HTTP/1.1
- RespStatus 304
- RespReason Not Modified
- RespReason Not Modified
- Debug "RES_MODE 0"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495668065.208002 0.000217 0.000075
- ReqAcct 409 0 409 367 0 367
- End


_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

On 31/05/2017 18:21, Dridi Boukelmoune wrote:
> On Wed, May 31, 2017 at 6:25 PM, Guillaume Quintard
>> I got that idea too, but the HIT after the purge return an object with a
>> large age.
>
> The age is something that could come from the backend. Does the VXID
> match the one that was just purged when a restart gets a hit?

As mentioned in the other email, a purge log entry does not include the
VXID as far as I can see, and "obj" is not available in vcl_purge either.

I can say that in my case there is definitely no Age header coming from
the back-end. Also as shown in the example I sent it is the 7th HIT on
that object.

Nigel

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

>> Amazingly enough I never looked at the logs of a purge, maybe ExpKill
>> could give us a VXID to then check against the hit. If only SomeoneElse(tm)
>> could spare me the time and look at it themselves and tell us (wink wink=).
>
>
> I'm very happy to help in any way I can. Please let me know anything I can
> do or information I can provide. I'm no C programmer (web developer/server
> admin), so can't help out with coding/patching/debugging[3], but anything
> else I can do, please let me know what you need.

Well, luckily I didn't write any C code to find out what purge logs
look like. I'm certainly not going to debug code I'm not familiar with ;)

I wrote a dummy test case instead:

varnishtest "purge logs"

server s1 {
rxreq
expect req.url == "/to-be-purged"
txresp
} -start

varnish v1 -vcl+backend {
sub vcl_recv {
if (req.method == "PURGE") {
return (purge);
}
}
} -start

client c1 {
txreq -url "/to-be-purged"
rxresp

txreq -req PURGE -url "/to-be-purged"
rxresp

txreq -req PURGE -url "/unknown"
rxresp
} -run

And then looked at the logs manually:

varnishtest test.vtc -v | grep vsl | less

Here's a sample:

[...]
**** v1 0.4 vsl| 1002 VCL_return b deliver
**** v1 0.4 vsl| 1002 Storage b malloc s0
[...]
**** v1 0.4 vsl| 0 ExpKill - EXP_When
p=0x7f420b027000 e=1496443420.703764200 f=0xe
**** v1 0.4 vsl| 0 ExpKill - EXP_expire
p=0x7f420b027000 e=-0.000092268 f=0x0
**** v1 0.4 vsl| 0 ExpKill - EXP_Expired x=1002 t=-0
[...]
**** v1 0.4 vsl| 1003 ReqMethod c PURGE
**** v1 0.4 vsl| 1003 ReqURL c /to-be-purged
[...]
**** v1 0.4 vsl| 1003 VCL_return c purge
**** v1 0.4 vsl| 1003 VCL_call c HASH
**** v1 0.4 vsl| 1003 VCL_return c lookup
**** v1 0.4 vsl| 1003 VCL_call c PURGE
**** v1 0.4 vsl| 1003 VCL_return c synth
[...]
**** v1 0.4 vsl| 1004 ReqMethod c PURGE
**** v1 0.4 vsl| 1004 ReqURL c /unknown
[...]
**** v1 0.4 vsl| 1004 VCL_return c purge
**** v1 0.4 vsl| 1004 VCL_call c HASH
**** v1 0.4 vsl| 1004 VCL_return c lookup
**** v1 0.4 vsl| 1004 VCL_call c PURGE
**** v1 0.4 vsl| 1004 VCL_return c synth
[...]

The interesting transaction id (VXID) is 1002.

So 1) purge-related logs will only show up with raw grouping in
varnishlog (which I find unfortunate but I should have remembered the
expiry thread would have been involved) and 2) we don't see in a
transaction log how many objects were actually purged (moved to the
expiry inbox).

The ExpKill records appear before because transactions commit their
logs when they finish by default.

> Would a cleanly installed server and absolute minimum VCL to reproduce this
> be useful? You would be welcome to have access to that server, if useful,
> once I've got it set up and producing the same problem.

Not yet, at this point we know that we were looking at an incomplete
picture so what you need to do is capture raw logs and we will be able
to get both a VXID and a timestamp from the ExpKill records (although
the timestamp for EXP_expire puzzles me).

See man varnishlog to see how to write (-w) and then read (-r) logs
to/from a file. When you notice the alleged bug, note the transaction
id and write the current logs (with the -d option) so that you can
pick up all the interesting bits at rest (instead of doing it on live
traffic).

> I can say that in my case there is definitely no Age header coming from the
> back-end. Also as shown in the example I sent it is the 7th HIT on that
> object.

Yes, smells like a bug. But before capturing logs, make sure to remove
Hash records from the vsl_mask (man varnishd) so we can confirm what's
being purged too.

I have a theory, a long shot that will only prove how unfamiliar I am
with this part of Varnish. Since the purge moves the object to the
expiry inbox, it could be that under load the restart may happen
before the expiry thread marks it as expired, thus creating a race
with the next lookup.

Cheers,
Dridi

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

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.

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.

Nigel

On 02/06/2017 18:08, Dridi Boukelmoune wrote:
>>> Amazingly enough I never looked at the logs of a purge, maybe ExpKill
>>> could give us a VXID to then check against the hit. If only SomeoneElse(tm)
>>> could spare me the time and look at it themselves and tell us (wink wink=).
>>
>>
>> I'm very happy to help in any way I can. Please let me know anything I can
>> do or information I can provide. I'm no C programmer (web developer/server
>> admin), so can't help out with coding/patching/debugging[3], but anything
>> else I can do, please let me know what you need.
>
> Well, luckily I didn't write any C code to find out what purge logs
> look like. I'm certainly not going to debug code I'm not familiar with ;)
>
> I wrote a dummy test case instead:
>
> varnishtest "purge logs"
>
> server s1 {
> rxreq
> expect req.url == "/to-be-purged"
> txresp
> } -start
>
> varnish v1 -vcl+backend {
> sub vcl_recv {
> if (req.method == "PURGE") {
> return (purge);
> }
> }
> } -start
>
> client c1 {
> txreq -url "/to-be-purged"
> rxresp
>
> txreq -req PURGE -url "/to-be-purged"
> rxresp
>
> txreq -req PURGE -url "/unknown"
> rxresp
> } -run
>
> And then looked at the logs manually:
>
> varnishtest test.vtc -v | grep vsl | less
>
> Here's a sample:
>
> [...]
> **** v1 0.4 vsl| 1002 VCL_return b deliver
> **** v1 0.4 vsl| 1002 Storage b malloc s0
> [...]
> **** v1 0.4 vsl| 0 ExpKill - EXP_When
> p=0x7f420b027000 e=1496443420.703764200 f=0xe
> **** v1 0.4 vsl| 0 ExpKill - EXP_expire
> p=0x7f420b027000 e=-0.000092268 f=0x0
> **** v1 0.4 vsl| 0 ExpKill - EXP_Expired x=1002 t=-0
> [...]
> **** v1 0.4 vsl| 1003 ReqMethod c PURGE
> **** v1 0.4 vsl| 1003 ReqURL c /to-be-purged
> [...]
> **** v1 0.4 vsl| 1003 VCL_return c purge
> **** v1 0.4 vsl| 1003 VCL_call c HASH
> **** v1 0.4 vsl| 1003 VCL_return c lookup
> **** v1 0.4 vsl| 1003 VCL_call c PURGE
> **** v1 0.4 vsl| 1003 VCL_return c synth
> [...]
> **** v1 0.4 vsl| 1004 ReqMethod c PURGE
> **** v1 0.4 vsl| 1004 ReqURL c /unknown
> [...]
> **** v1 0.4 vsl| 1004 VCL_return c purge
> **** v1 0.4 vsl| 1004 VCL_call c HASH
> **** v1 0.4 vsl| 1004 VCL_return c lookup
> **** v1 0.4 vsl| 1004 VCL_call c PURGE
> **** v1 0.4 vsl| 1004 VCL_return c synth
> [...]
>
> The interesting transaction id (VXID) is 1002.
>
> So 1) purge-related logs will only show up with raw grouping in
> varnishlog (which I find unfortunate but I should have remembered the
> expiry thread would have been involved) and 2) we don't see in a
> transaction log how many objects were actually purged (moved to the
> expiry inbox).
>
> The ExpKill records appear before because transactions commit their
> logs when they finish by default.
>
>> Would a cleanly installed server and absolute minimum VCL to reproduce this
>> be useful? You would be welcome to have access to that server, if useful,
>> once I've got it set up and producing the same problem.
>
> Not yet, at this point we know that we were looking at an incomplete
> picture so what you need to do is capture raw logs and we will be able
> to get both a VXID and a timestamp from the ExpKill records (although
> the timestamp for EXP_expire puzzles me).
>
> See man varnishlog to see how to write (-w) and then read (-r) logs
> to/from a file. When you notice the alleged bug, note the transaction
> id and write the current logs (with the -d option) so that you can
> pick up all the interesting bits at rest (instead of doing it on live
> traffic).
>
>> I can say that in my case there is definitely no Age header coming from the
>> back-end. Also as shown in the example I sent it is the 7th HIT on that
>> object.
>
> Yes, smells like a bug. But before capturing logs, make sure to remove
> Hash records from the vsl_mask (man varnishd) so we can confirm what's
> being purged too.
>
> I have a theory, a long shot that will only prove how unfamiliar I am
> with this part of Varnish. Since the purge moves the object to the
> expiry inbox, it could be that under load the restart may happen
> before the expiry thread marks it as expired, thus creating a race
> with the next lookup.
>
> Cheers,
> Dridi
>

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

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)

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.

So this seems to be in some way related to how long the objects have
been in the cache.

Nigel

On 16/06/2017 13:27, Nigel Peck wrote:
>
> 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.
>
> 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.
>
> Nigel
>
> On 02/06/2017 18:08, Dridi Boukelmoune wrote:
>>>> Amazingly enough I never looked at the logs of a purge, maybe ExpKill
>>>> could give us a VXID to then check against the hit. If only
>>>> SomeoneElse(tm)
>>>> could spare me the time and look at it themselves and tell us (wink
>>>> wink=).
>>>
>>>
>>> I'm very happy to help in any way I can. Please let me know anything
>>> I can
>>> do or information I can provide. I'm no C programmer (web
>>> developer/server
>>> admin), so can't help out with coding/patching/debugging[3], but
>>> anything
>>> else I can do, please let me know what you need.
>>
>> Well, luckily I didn't write any C code to find out what purge logs
>> look like. I'm certainly not going to debug code I'm not familiar with ;)
>>
>> I wrote a dummy test case instead:
>>
>> varnishtest "purge logs"
>>
>> server s1 {
>> rxreq
>> expect req.url == "/to-be-purged"
>> txresp
>> } -start
>>
>> varnish v1 -vcl+backend {
>> sub vcl_recv {
>> if (req.method == "PURGE") {
>> return (purge);
>> }
>> }
>> } -start
>>
>> client c1 {
>> txreq -url "/to-be-purged"
>> rxresp
>>
>> txreq -req PURGE -url "/to-be-purged"
>> rxresp
>>
>> txreq -req PURGE -url "/unknown"
>> rxresp
>> } -run
>>
>> And then looked at the logs manually:
>>
>> varnishtest test.vtc -v | grep vsl | less
>>
>> Here's a sample:
>>
>> [...]
>> **** v1 0.4 vsl| 1002 VCL_return b deliver
>> **** v1 0.4 vsl| 1002 Storage b malloc s0
>> [...]
>> **** v1 0.4 vsl| 0 ExpKill - EXP_When
>> p=0x7f420b027000 e=1496443420.703764200 f=0xe
>> **** v1 0.4 vsl| 0 ExpKill - EXP_expire
>> p=0x7f420b027000 e=-0.000092268 f=0x0
>> **** v1 0.4 vsl| 0 ExpKill - EXP_Expired
>> x=1002 t=-0
>> [...]
>> **** v1 0.4 vsl| 1003 ReqMethod c PURGE
>> **** v1 0.4 vsl| 1003 ReqURL c /to-be-purged
>> [...]
>> **** v1 0.4 vsl| 1003 VCL_return c purge
>> **** v1 0.4 vsl| 1003 VCL_call c HASH
>> **** v1 0.4 vsl| 1003 VCL_return c lookup
>> **** v1 0.4 vsl| 1003 VCL_call c PURGE
>> **** v1 0.4 vsl| 1003 VCL_return c synth
>> [...]
>> **** v1 0.4 vsl| 1004 ReqMethod c PURGE
>> **** v1 0.4 vsl| 1004 ReqURL c /unknown
>> [...]
>> **** v1 0.4 vsl| 1004 VCL_return c purge
>> **** v1 0.4 vsl| 1004 VCL_call c HASH
>> **** v1 0.4 vsl| 1004 VCL_return c lookup
>> **** v1 0.4 vsl| 1004 VCL_call c PURGE
>> **** v1 0.4 vsl| 1004 VCL_return c synth
>> [...]
>>
>> The interesting transaction id (VXID) is 1002.
>>
>> So 1) purge-related logs will only show up with raw grouping in
>> varnishlog (which I find unfortunate but I should have remembered the
>> expiry thread would have been involved) and 2) we don't see in a
>> transaction log how many objects were actually purged (moved to the
>> expiry inbox).
>>
>> The ExpKill records appear before because transactions commit their
>> logs when they finish by default.
>>
>>> Would a cleanly installed server and absolute minimum VCL to
>>> reproduce this
>>> be useful? You would be welcome to have access to that server, if
>>> useful,
>>> once I've got it set up and producing the same problem.
>>
>> Not yet, at this point we know that we were looking at an incomplete
>> picture so what you need to do is capture raw logs and we will be able
>> to get both a VXID and a timestamp from the ExpKill records (although
>> the timestamp for EXP_expire puzzles me).
>>
>> See man varnishlog to see how to write (-w) and then read (-r) logs
>> to/from a file. When you notice the alleged bug, note the transaction
>> id and write the current logs (with the -d option) so that you can
>> pick up all the interesting bits at rest (instead of doing it on live
>> traffic).
>>
>>> I can say that in my case there is definitely no Age header coming
>>> from the
>>> back-end. Also as shown in the example I sent it is the 7th HIT on that
>>> object.
>>
>> Yes, smells like a bug. But before capturing logs, make sure to remove
>> Hash records from the vsl_mask (man varnishd) so we can confirm what's
>> being purged too.
>>
>> I have a theory, a long shot that will only prove how unfamiliar I am
>> with this part of Varnish. Since the purge moves the object to the
>> expiry inbox, it could be that under load the restart may happen
>> before the expiry thread marks it as expired, thus creating a race
>> with the next lookup.
>>
>> Cheers,
>> Dridi
>>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

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?
The period when the purge occurs may be important...

--
Guillaume Quintard

On Fri, Jun 16, 2017 at 9:09 PM, Nigel Peck <np.lists@sharphosting.uk>
wrote:

>
> 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)
>
> 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.
>
> So this seems to be in some way related to how long the objects have been
> in the cache.
>
> Nigel
>
>
> On 16/06/2017 13:27, Nigel Peck wrote:
>
>>
>> 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.
>>
>> 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.
>>
>> Nigel
>>
>> On 02/06/2017 18:08, Dridi Boukelmoune wrote:
>>
>>> Amazingly enough I never looked at the logs of a purge, maybe ExpKill
>>>>> could give us a VXID to then check against the hit. If only
>>>>> SomeoneElse(tm)
>>>>> could spare me the time and look at it themselves and tell us (wink
>>>>> wink=).
>>>>>
>>>>
>>>>
>>>> I'm very happy to help in any way I can. Please let me know anything I
>>>> can
>>>> do or information I can provide. I'm no C programmer (web
>>>> developer/server
>>>> admin), so can't help out with coding/patching/debugging[3], but
>>>> anything
>>>> else I can do, please let me know what you need.
>>>>
>>>
>>> Well, luckily I didn't write any C code to find out what purge logs
>>> look like. I'm certainly not going to debug code I'm not familiar with ;)
>>>
>>> I wrote a dummy test case instead:
>>>
>>> varnishtest "purge logs"
>>>
>>> server s1 {
>>> rxreq
>>> expect req.url == "/to-be-purged"
>>> txresp
>>> } -start
>>>
>>> varnish v1 -vcl+backend {
>>> sub vcl_recv {
>>> if (req.method == "PURGE") {
>>> return (purge);
>>> }
>>> }
>>> } -start
>>>
>>> client c1 {
>>> txreq -url "/to-be-purged"
>>> rxresp
>>>
>>> txreq -req PURGE -url "/to-be-purged"
>>> rxresp
>>>
>>> txreq -req PURGE -url "/unknown"
>>> rxresp
>>> } -run
>>>
>>> And then looked at the logs manually:
>>>
>>> varnishtest test.vtc -v | grep vsl | less
>>>
>>> Here's a sample:
>>>
>>> [...]
>>> **** v1 0.4 vsl| 1002 VCL_return b deliver
>>> **** v1 0.4 vsl| 1002 Storage b malloc s0
>>> [...]
>>> **** v1 0.4 vsl| 0 ExpKill - EXP_When
>>> p=0x7f420b027000 e=1496443420.703764200 f=0xe
>>> **** v1 0.4 vsl| 0 ExpKill - EXP_expire
>>> p=0x7f420b027000 e=-0.000092268 f=0x0
>>> **** v1 0.4 vsl| 0 ExpKill - EXP_Expired x=1002
>>> t=-0
>>> [...]
>>> **** v1 0.4 vsl| 1003 ReqMethod c PURGE
>>> **** v1 0.4 vsl| 1003 ReqURL c /to-be-purged
>>> [...]
>>> **** v1 0.4 vsl| 1003 VCL_return c purge
>>> **** v1 0.4 vsl| 1003 VCL_call c HASH
>>> **** v1 0.4 vsl| 1003 VCL_return c lookup
>>> **** v1 0.4 vsl| 1003 VCL_call c PURGE
>>> **** v1 0.4 vsl| 1003 VCL_return c synth
>>> [...]
>>> **** v1 0.4 vsl| 1004 ReqMethod c PURGE
>>> **** v1 0.4 vsl| 1004 ReqURL c /unknown
>>> [...]
>>> **** v1 0.4 vsl| 1004 VCL_return c purge
>>> **** v1 0.4 vsl| 1004 VCL_call c HASH
>>> **** v1 0.4 vsl| 1004 VCL_return c lookup
>>> **** v1 0.4 vsl| 1004 VCL_call c PURGE
>>> **** v1 0.4 vsl| 1004 VCL_return c synth
>>> [...]
>>>
>>> The interesting transaction id (VXID) is 1002.
>>>
>>> So 1) purge-related logs will only show up with raw grouping in
>>> varnishlog (which I find unfortunate but I should have remembered the
>>> expiry thread would have been involved) and 2) we don't see in a
>>> transaction log how many objects were actually purged (moved to the
>>> expiry inbox).
>>>
>>> The ExpKill records appear before because transactions commit their
>>> logs when they finish by default.
>>>
>>> Would a cleanly installed server and absolute minimum VCL to reproduce
>>>> this
>>>> be useful? You would be welcome to have access to that server, if
>>>> useful,
>>>> once I've got it set up and producing the same problem.
>>>>
>>>
>>> Not yet, at this point we know that we were looking at an incomplete
>>> picture so what you need to do is capture raw logs and we will be able
>>> to get both a VXID and a timestamp from the ExpKill records (although
>>> the timestamp for EXP_expire puzzles me).
>>>
>>> See man varnishlog to see how to write (-w) and then read (-r) logs
>>> to/from a file. When you notice the alleged bug, note the transaction
>>> id and write the current logs (with the -d option) so that you can
>>> pick up all the interesting bits at rest (instead of doing it on live
>>> traffic).
>>>
>>> I can say that in my case there is definitely no Age header coming from
>>>> the
>>>> back-end. Also as shown in the example I sent it is the 7th HIT on that
>>>> object.
>>>>
>>>
>>> Yes, smells like a bug. But before capturing logs, make sure to remove
>>> Hash records from the vsl_mask (man varnishd) so we can confirm what's
>>> being purged too.
>>>
>>> I have a theory, a long shot that will only prove how unfamiliar I am
>>> with this part of Varnish. Since the purge moves the object to the
>>> expiry inbox, it could be that under load the restart may happen
>>> before the expiry thread marks it as expired, thus creating a race
>>> with the next lookup.
>>>
>>> Cheers,
>>> Dridi
>>>
>>>
>> _______________________________________________
>> varnish-misc mailing list
>> varnish-misc@varnish-cache.org
>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>

Sure, that's something I can understand! Will gather some data over the
next couple of days for different time periods and configurations.

On 23/06/2017 04:09, Guillaume Quintard wrote:
> 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?
> The period when the purge occurs may be important...
>
> --
> Guillaume Quintard
>
> On Fri, Jun 16, 2017 at 9:09 PM, Nigel Peck <np.lists@sharphosting.uk
> <mailto:np.lists@sharphosting.uk>> wrote:
>
>
> 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)
>
> 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.
>
> So this seems to be in some way related to how long the objects have
> been in the cache.
>
> Nigel
>
>
> On 16/06/2017 13:27, Nigel Peck wrote:
>
>
> 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.
>
> 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.
>
> Nigel
>
> On 02/06/2017 18:08, Dridi Boukelmoune wrote:
>
> Amazingly enough I never looked at the logs of a
> purge, maybe ExpKill
> could give us a VXID to then check against the hit.
> If only SomeoneElse(tm)
> could spare me the time and look at it themselves
> and tell us (wink wink=).
>
>
>
> I'm very happy to help in any way I can. Please let me
> know anything I can
> do or information I can provide. I'm no C programmer
> (web developer/server
> admin), so can't help out with
> coding/patching/debugging[3], but anything
> else I can do, please let me know what you need.
>
>
> Well, luckily I didn't write any C code to find out what
> purge logs
> look like. I'm certainly not going to debug code I'm not
> familiar with ;)
>
> I wrote a dummy test case instead:
>
> varnishtest "purge logs"
>
> server s1 {
> rxreq
> expect req.url == "/to-be-purged"
> txresp
> } -start
>
> varnish v1 -vcl+backend {
> sub vcl_recv {
> if (req.method == "PURGE") {
> return (purge);
> }
> }
> } -start
>
> client c1 {
> txreq -url "/to-be-purged"
> rxresp
>
> txreq -req PURGE -url "/to-be-purged"
> rxresp
>
> txreq -req PURGE -url "/unknown"
> rxresp
> } -run
>
> And then looked at the logs manually:
>
> varnishtest test.vtc -v | grep vsl | less
>
> Here's a sample:
>
> [...]
> **** v1 0.4 vsl| 1002 VCL_return b deliver
> **** v1 0.4 vsl| 1002 Storage b malloc s0
> [...]
> **** v1 0.4 vsl| 0 ExpKill - EXP_When
> p=0x7f420b027000 e=1496443420.703764200 f=0xe
> **** v1 0.4 vsl| 0 ExpKill -
> EXP_expire
> p=0x7f420b027000 e=-0.000092268 f=0x0
> **** v1 0.4 vsl| 0 ExpKill -
> EXP_Expired x=1002 t=-0
> [...]
> **** v1 0.4 vsl| 1003 ReqMethod c PURGE
> **** v1 0.4 vsl| 1003 ReqURL c
> /to-be-purged
> [...]
> **** v1 0.4 vsl| 1003 VCL_return c purge
> **** v1 0.4 vsl| 1003 VCL_call c HASH
> **** v1 0.4 vsl| 1003 VCL_return c lookup
> **** v1 0.4 vsl| 1003 VCL_call c PURGE
> **** v1 0.4 vsl| 1003 VCL_return c synth
> [...]
> **** v1 0.4 vsl| 1004 ReqMethod c PURGE
> **** v1 0.4 vsl| 1004 ReqURL c /unknown
> [...]
> **** v1 0.4 vsl| 1004 VCL_return c purge
> **** v1 0.4 vsl| 1004 VCL_call c HASH
> **** v1 0.4 vsl| 1004 VCL_return c lookup
> **** v1 0.4 vsl| 1004 VCL_call c PURGE
> **** v1 0.4 vsl| 1004 VCL_return c synth
> [...]
>
> The interesting transaction id (VXID) is 1002.
>
> So 1) purge-related logs will only show up with raw grouping in
> varnishlog (which I find unfortunate but I should have
> remembered the
> expiry thread would have been involved) and 2) we don't see in a
> transaction log how many objects were actually purged (moved
> to the
> expiry inbox).
>
> The ExpKill records appear before because transactions
> commit their
> logs when they finish by default.
>
> Would a cleanly installed server and absolute minimum
> VCL to reproduce this
> be useful? You would be welcome to have access to that
> server, if useful,
> once I've got it set up and producing the same problem.
>
>
> Not yet, at this point we know that we were looking at an
> incomplete
> picture so what you need to do is capture raw logs and we
> will be able
> to get both a VXID and a timestamp from the ExpKill records
> (although
> the timestamp for EXP_expire puzzles me).
>
> See man varnishlog to see how to write (-w) and then read
> (-r) logs
> to/from a file. When you notice the alleged bug, note the
> transaction
> id and write the current logs (with the -d option) so that
> you can
> pick up all the interesting bits at rest (instead of doing
> it on live
> traffic).
>
> I can say that in my case there is definitely no Age
> header coming from the
> back-end. Also as shown in the example I sent it is the
> 7th HIT on that
> object.
>
>
> Yes, smells like a bug. But before capturing logs, make sure
> to remove
> Hash records from the vsl_mask (man varnishd) so we can
> confirm what's
> being purged too.
>
> I have a theory, a long shot that will only prove how
> unfamiliar I am
> with this part of Varnish. Since the purge moves the object
> to the
> expiry inbox, it could be that under load the restart may happen
> before the expiry thread marks it as expired, thus creating
> a race
> with the next lookup.
>
> Cheers,
> Dridi
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> <mailto:varnish-misc@varnish-cache.org>
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc <https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc>
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org <mailto:varnish-misc@varnish-cache.org>
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
> <https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc>
>
>

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc