search

varnish / varnish-modules

Collection of Varnish Cache modules (vmods) by Varnish Software
Other
185 stars 86 forks source link

xkey purged but still serving cached response #135

Closed jonbev closed 5 years ago

jonbev commented 5 years ago

Looking at the logs I can see that the xkey-purge is purging objects - "RespReason Purged 27 objects, expired 0 objects" but we are still seeing cached responses that are tagged in this example this "property-235". It seems to work ok sometimes as we have two servers running the same ami on amazon and we see this issue with only one of the servers, also some objects with the same tag are correctly purged but others are not. If we replace the server it will work ok for a time and then fail again. I'm not sure how we can debug this as we can't reliably reproduce the problem. Both servers are receiving the invalidations and the cache age of the responses is high so it's not a backend issue.

Is there a way to list objects that have a certain tag?

Any suggestions on how to debug this?

There is a bit more detail on here - https://github.com/FriendsOfSymfony/FOSHttpCache/issues/448

<< Request >> 31474814 Begin req 31474813 rxreq Timestamp Start: 1554714883.640552 0.000000 0.000000 Timestamp Req: 1554714883.640552 0.000000 0.000000 ReqStart 10.100.1.50 38442 a0 ReqMethod PURGEKEYS ReqURL / ReqProtocol HTTP/1.1 ReqHeader Host: xxxx.api.tabs-software.co.uk ReqHeader User-Agent: GuzzleHttp/6.3.3 curl/7.47.0 PHP/7.1.27-1+ubuntu16.04.1+deb.sury.org+1 ReqHeader xkey-purge: property-235 property-235 property ReqHeader Connection: Close ReqHeader X-Forwarded-For: 10.100.1.50 VCL_call RECV ReqUnset X-Forwarded-For: 10.100.1.50 ReqHeader X-Forwarded-For: 10.100.1.50 ReqHeader CloudFront-Forwarded-Proto: https VCL_acl MATCH invalidators "10.100.1.0"/24 ReqHeader n-gone: 0 ReqHeader n-softgone: 0 ReqUnset n-gone: 0 ReqHeader n-gone: 27 VCL_return synth VCL_call HASH VCL_return lookup Timestamp Process: 1554714883.640706 0.000154 0.000154 RespHeader Date: Mon, 08 Apr 2019 09:14:43 GMT RespHeader Server: Varnish RespHeader X-Varnish: 31474814 RespProtocol HTTP/1.1 RespStatus 200 RespReason OK RespReason Purged 27 objects, expired 0 objects VCL_call SYNTH RespUnset Server: Varnish RespUnset X-Varnish: 31474814 RespHeader X-Cache-Action: SYNTH VCL_return deliver RespHeader Content-Length: 233 Storage malloc Transient RespHeader Accept-Ranges: bytes RespHeader Connection: close Timestamp Resp: 1554714883.640742 0.000190 0.000036 ReqAcct 212 0 212 175 233 408 End

PeteLawrence commented 5 years ago

Here's a little more detail:

A route is requested, which is tagged with 'crontask' and is served from the cache:

$ http GET localhost/v2/crontask 'Host:xxxx.api.tabs-software.co.uk' 'Authorization:Bearer XXXXX' -p hH
GET /v2/crontask HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Authorization: Bearer XXXXX
Connection: keep-alive
Host: xxxx.api.tabs-software.co.uk
User-Agent: HTTPie/0.9.8

HTTP/1.1 200 OK
Accept-Ranges: bytes
Access-Control-Allow-Origin: *
Access-Control-Expose-Headers: content-location, location
Connection: keep-alive
Content-Encoding: gzip
Content-Length: 7275
Content-Type: application/json
Date: Thu, 11 Apr 2019 09:30:40 GMT
Vary: Accept-Encoding, X-User-Context-Hash
X-Cache-Action: HIT
X-Cache-Age: 533894.992
X-Cache-Hits: 4504
X-Cache-Storage: storage.default
X-Cache-TTL: 70904.383
X-Cache-Tags: crontask
X-Controller-Name: crontask_list

A PURGEKEYS request is sent to invalidate anything tagged 'crontask'. Note that in this instance 0 objects get purged:

$ http PURGEKEYS localhost/ 'xkey-purge:crontask' -p hHb
PURGEKEYS / HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Content-Length: 0
Host: xxxx.api.tabs-software.co.uk
User-Agent: HTTPie/0.9.8
xkey-purge: crontask

HTTP/1.1 200 Purged 0 objects, expired 0 objects
Accept-Ranges: bytes
Connection: keep-alive
Content-Length: 231
Date: Wed, 17 Apr 2019 13:46:57 GMT
X-Cache-Action: SYNTH

<!DOCTYPE html>
<html>
  <head>
    <title>200 Purged 0 objects, expired 0 objects</title>
  </head>
  <body>
    <h1>Status: 200</h1>
    <p>Purged 0 objects, expired 0 objects</p>
    <hr>
    <p>tabs 2 API</p>
  </body>
</html>

Another request to the original route shows that the object hasn't been expired from the cache:

$ http GET localhost/v2/crontask 'Host:xxxx.api.tabs-software.co.uk' 'Authorization:Bearer XXXXX' -p hH
GET /v2/crontask HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Authorization: Bearer XXXXX
Connection: keep-alive
Host: xxxx.api.tabs-software.co.uk
User-Agent: HTTPie/0.9.8

HTTP/1.1 200 OK
Accept-Ranges: bytes
Access-Control-Allow-Origin: *
Access-Control-Expose-Headers: content-location, location
Connection: keep-alive
Content-Encoding: gzip
Content-Length: 7275
Content-Type: application/json
Date: Thu, 11 Apr 2019 09:30:40 GMT
Vary: Accept-Encoding, X-User-Context-Hash
X-Cache-Action: HIT
X-Cache-Age: 534117.553
X-Cache-Hits: 4508
X-Cache-Storage: storage.default
X-Cache-TTL: 70681.822
X-Cache-Tags: crontask
X-Controller-Name: crontask_list

The corresponding output from varnishlog:

*   << Request  >> 93915826  
-   Begin          req 93915825 rxreq
-   Timestamp      Start: 1555507675.177348 0.000000 0.000000
-   Timestamp      Req: 1555507675.177348 0.000000 0.000000
-   ReqStart       127.0.0.1 42800 a0
-   ReqMethod      PURGEKEYS
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: localhost
-   ReqHeader      User-Agent: HTTPie/0.9.8
-   ReqHeader      Accept-Encoding: gzip, deflate
-   ReqHeader      Accept: */*
-   ReqHeader      Connection: keep-alive
-   ReqHeader      xkey-purge: crontask
-   ReqHeader      Content-Length: 0
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_call       RECV
-   ReqUnset       X-Forwarded-For: 127.0.0.1
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   ReqHeader      CloudFront-Forwarded-Proto: https
-   VCL_acl        MATCH invalidators "localhost"
-   ReqHeader      n-gone: 0
-   ReqHeader      n-softgone: 0
-   ReqUnset       n-gone: 0
-   ReqHeader      n-gone: 0
-   VCL_return     synth
-   ReqUnset       Accept-Encoding: gzip, deflate
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   Timestamp      Process: 1555507675.177391 0.000043 0.000043
-   RespHeader     Date: Wed, 17 Apr 2019 13:27:55 GMT
-   RespHeader     Server: Varnish
-   RespHeader     X-Varnish: 93915826
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespReason     Purged 0 objects, expired 0 objects
-   VCL_call       SYNTH
-   RespUnset      Server: Varnish
-   RespUnset      X-Varnish: 93915826
-   RespHeader     X-Cache-Action: SYNTH
-   VCL_return     deliver
-   RespHeader     Content-Length: 231
-   Storage        malloc Transient
-   RespHeader     Accept-Ranges: bytes
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1555507675.177434 0.000087 0.000043
-   ReqAcct        177 0 177 179 231 410
-   End

The xkey part of the varnish config file:

sub fos_tags_xkey_recv {
    if (req.method == "PURGEKEYS") {
        if (!client.ip ~ invalidators) {
            return (synth(405, "Not allowed"));
        }

        # If neither of the headers are provided we return 400 to simplify detecting wrong configuration
        if (!req.http.xkey-purge && !req.http.xkey-softpurge) {
            return (synth(400));
        }

        # Based on provided header invalidate (purge) and/or expire (softpurge) the tagged content
        set req.http.n-gone = 0;
        set req.http.n-softgone = 0;
        if (req.http.xkey-purge) {
            set req.http.n-gone = xkey.purge(req.http.xkey-purge);
        }

        if (req.http.xkey-softpurge) {
            set req.http.n-softgone = xkey.softpurge(req.http.xkey-softpurge);
        }

        return (synth(200, "Purged "+req.http.n-gone+" objects, expired "+req.http.n-softgone+" objects"));
    }
}

Versions:

Ubuntu 18.04.2
varnishd (varnish-6.0.3 revision 7d1ded3aa033a018317dbafc61587026ea2ef8a3)
xkey module compiled from the latest source on the 29th March

NB. We had previously been using varnish 5, but upgraded to 6 in an attempt to fix the problem, but without success.

dridi commented 5 years ago

I don't see enough because there are no logs and no VCL snippet from the backend side, but it looks like you expect vmod-xkey to pick up keys from X-Cache-Tags headers.

See here: https://github.com/varnish/varnish-modules/blob/0.15.0/docs/vmod_xkey.rst#description

Hash keys are specified in the xkey response header.

So what you need to do in vcl_backend_response is something like:

if (beresp.http.X-Cache-Tags) {
    set beresp.http.XKey = beresp.http.X-Cache-Tags;
}
PeteLawrence commented 5 years ago

Hi @Dridi,

Good spot! We do normally use the xkey response header, but have found an edge case where a newly started instance would serve the wrong headers whilst it was being bootstrapped.

Thanks ever so much for your help!

Pete

@jonbev I think you can probably close this now.

jonbev commented 5 years ago

Thanks