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

Reply via email to