Unexplained Cache MISSes

Nigel Peck np.lists at sharphosting.uk
Thu May 25 01:59:39 CEST 2017


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 at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc



More information about the varnish-misc mailing list