Varnish 4: how to purge cache with cookies

Question

Our software uses a cookie "selected_language" when people change language from Spanish to anything else. By default the cookie is not set.

We need to cache our site taking into account the language, so our index.php is cached several times,one for each language.

Our hash function uses language cookie (We get more cookies but they are removed inside vcl_recv, just the language cookie (if any) gets to the hash routine:

sub vcl_hash {
  hash_data(req.url);
  if (req.http.host) {
    hash_data(req.http.host);
  } else {
    hash_data(server.ip);
  }
  if (req.http.Cookie) {
    hash_data(req.http.Cookie);
  }
}

Our problem comes when we want to purge our cache. If we purge our index webpage, without cookies (spanish version), everything works ok:

curl -X PURGE  http://www.arasaac.org/index.php

However if we try to purge our index webpage with cookies (english version), it does nothing. I think purge uses hash so it should work if I send the related cookie.

Our purge code:

sub vcl_purge {
  # Only handle actual PURGE HTTP methods, everything else is discarded
  if (req.method != "PURGE") {
    # restart request
    set req.http.X-Purge = "Yes";
    return(restart);
  }
}

Inside vcl_recv:

  # Allow purging
  if (req.method == "PURGE") {
#    if (!client.ip ~ purge) { # purge is the ACL defined at the begining
      # Not from an allowed IP? Then die with an error.
#      return (synth(405, "This IP is not allowed to send PURGE requests."));
#    }
    # If you got this stage (and didn't error out above), purge the cached result
    return (purge);
  }

These are all the logs in case they're needed...

I ask again for the page, that is cached:

*   << Request  >> 262149    
-   Begin          req 262148 rxreq
-   Timestamp      Start: 1488455938.456980 0.000000 0.000000
-   Timestamp      Req: 1488455938.456980 0.000000 0.000000
-   ReqStart       172.20.0.3 51672
-   ReqMethod      GET
-   ReqURL         /index.php
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: www.arasaac.org
-   ReqHeader      Connection: close
-   ReqHeader      X-Real-IP: 172.20.0.1
-   ReqHeader      X-Forwarded-For: 172.20.0.1
-   ReqHeader      X-Forwarded-Proto: http
-   ReqHeader      X-Forwarded-Ssl: off
-   ReqHeader      X-Forwarded-Port: 80
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36
-   ReqHeader      Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   ReqHeader      Referer: http://www.arasaac.org/index.php
-   ReqHeader      Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Language: es-ES,es;q=0.8,en;q=0.6
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _ga=GA1.2.99795965.1488449144; _gat=1
-   ReqUnset       X-Forwarded-For: 172.20.0.1
-   ReqHeader      X-Forwarded-For: 172.20.0.1, 172.20.0.3
-   VCL_call       RECV
-   ReqUnset       Host: www.arasaac.org
-   ReqHeader      Host: www.arasaac.org
-   ReqURL         /
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _ga=GA1.2.99795965.1488449144; _gat=1
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _ga=GA1.2.99795965.1488449144; _gat=1
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _ga=GA1.2.99795965.1488449144; _gat=1
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _ga=GA1.2.99795965.1488449144; _gat=1
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _ga=GA1.2.99795965.1488449144; _gat=1
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   VCL_return     hash
-   ReqUnset       Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   Hit            3
-   VCL_call       HIT
-   VCL_return     deliver
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Date: Thu, 02 Mar 2017 11:57:52 GMT
-   RespHeader     Server: Apache/2.4.10 (Debian)
-   RespHeader     X-Powered-By: PHP/5.6.30
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Content-Encoding: gzip
-   RespHeader     Content-Length: 5379
-   RespHeader     Content-Type: text/html; charset=UTF-8
-   RespHeader     cache-control: public, max-age = 300
-   RespHeader     log: ha entrado aquí
-   RespHeader     X-CacheReason: varnishcache
-   RespHeader     X-Varnish: 262149 3
-   RespHeader     Age: 66
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache: HIT
-   RespHeader     X-Cache-Hits: 1
-   RespUnset      X-Powered-By: PHP/5.6.30
-   RespUnset      Server: Apache/2.4.10 (Debian)
-   RespUnset      X-Varnish: 262149 3
-   RespUnset      Via: 1.1 varnish-v4
-   VCL_return     deliver
-   Timestamp      Process: 1488455938.457118 0.000138 0.000138
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1488455938.457194 0.000215 0.000077
-   ReqAcct        658 0 658 336 5379 5715
-   End

I try to purge the page, so I send the cookie:

curl -X PURGE --cookie "selected_language=en" http://www.arasaac.org/index.php

Logs seem good for me:

*   << Request  >> 28        
-   Begin          req 27 rxreq
-   Timestamp      Start: 1488456128.433721 0.000000 0.000000
-   Timestamp      Req: 1488456128.433721 0.000000 0.000000
-   ReqStart       172.20.0.3 53286
-   ReqMethod      PURGE
-   ReqURL         /index.php
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: www.arasaac.org
-   ReqHeader      Connection: close
-   ReqHeader      X-Real-IP: 172.20.0.1
-   ReqHeader      X-Forwarded-For: 172.20.0.1
-   ReqHeader      X-Forwarded-Proto: http
-   ReqHeader      X-Forwarded-Ssl: off
-   ReqHeader      X-Forwarded-Port: 80
-   ReqHeader      User-Agent: curl/7.35.0
-   ReqHeader      Accept: */*
-   ReqHeader      Cookie: selected_language=en;
-   ReqUnset       X-Forwarded-For: 172.20.0.1
-   ReqHeader      X-Forwarded-For: 172.20.0.1, 172.20.0.3
-   VCL_call       RECV
-   ReqUnset       Host: www.arasaac.org
-   ReqHeader      Host: www.arasaac.org
-   ReqURL         /
-   VCL_return     purge
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PURGE
-   VCL_return     synth
-   Timestamp      Process: 1488456128.433754 0.000033 0.000033
-   RespHeader     Date: Thu, 02 Mar 2017 12:02:08 GMT
-   RespHeader     Server: Varnish
-   RespHeader     X-Varnish: 28
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespReason     Purged
-   VCL_call       SYNTH
-   VCL_return     deliver
-   RespHeader     Content-Length: 0
-   Storage        malloc Transient
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1488456128.433792 0.000070 0.000038
-   ReqAcct        261 0 261 152 0 152
-   End

However if I load again index.php in the browser, the cache is still there:

<< Request  >> 30        
-   Begin          req 29 rxreq
-   Timestamp      Start: 1488456171.661988 0.000000 0.000000
-   Timestamp      Req: 1488456171.661988 0.000000 0.000000
-   ReqStart       172.20.0.3 53688
-   ReqMethod      GET
-   ReqURL         /index.php
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: www.arasaac.org
-   ReqHeader      Connection: close
-   ReqHeader      X-Real-IP: 172.20.0.1
-   ReqHeader      X-Forwarded-For: 172.20.0.1
-   ReqHeader      X-Forwarded-Proto: http
-   ReqHeader      X-Forwarded-Ssl: off
-   ReqHeader      X-Forwarded-Port: 80
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36
-   ReqHeader      Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   ReqHeader      Referer: http://www.arasaac.org/index.php
-   ReqHeader      Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Language: es-ES,es;q=0.8,en;q=0.6
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
-   ReqUnset       X-Forwarded-For: 172.20.0.1
-   ReqHeader      X-Forwarded-For: 172.20.0.1, 172.20.0.3
-   VCL_call       RECV
-   ReqUnset       Host: www.arasaac.org
-   ReqHeader      Host: www.arasaac.org
-   ReqURL         /
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   ReqUnset       Cookie: selected_language=en; 
-   ReqHeader      Cookie: selected_language=en; 
-   VCL_return     hash
-   ReqUnset       Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   Hit            3
-   VCL_call       HIT
-   VCL_return     deliver
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Date: Thu, 02 Mar 2017 11:57:52 GMT
-   RespHeader     Server: Apache/2.4.10 (Debian)
-   RespHeader     X-Powered-By: PHP/5.6.30
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Content-Encoding: gzip
-   RespHeader     Content-Length: 5379
-   RespHeader     Content-Type: text/html; charset=UTF-8
-   RespHeader     cache-control: public, max-age = 300
-   RespHeader     log: ha entrado aquí
-   RespHeader     X-CacheReason: varnishcache
-   RespHeader     X-Varnish: 30 3
-   RespHeader     Age: 299
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     X-Cache: HIT
-   RespHeader     X-Cache-Hits: 2
-   RespUnset      X-Powered-By: PHP/5.6.30
-   RespUnset      Server: Apache/2.4.10 (Debian)
-   RespUnset      X-Varnish: 30 3
-   RespUnset      Via: 1.1 varnish-v4
-   VCL_return     deliver
-   Timestamp      Process: 1488456171.662050 0.000061 0.000061
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1488456171.662105 0.000117 0.000056
-   ReqAcct        658 0 658 337 5379 5716
-   End

By the way.. how is it that ReqHeader and Reqset lines in logs related to cookies are repeated many times?

    -   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
    -   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
    -   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
    -   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
    -   ReqUnset       Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; _ga=GA1.2.99795965.1488449144
    -   ReqHeader      Cookie: PHPSESSID=242b73bc8a560b89308009e05af7eefd; selected_language=en; _gat=1; 
...

Danila Vershinin Danila Vershinin · Accepted Answer · 2017-03-02T13:00:06

My wild guess is that when you cleaning the cookies you end up with:

"selected_language=en; " (with trailing space)

Whereas in your purge request you're passing

"selected_language=en;"

Try to send purge like this:

curl -X PURGE --cookie "selected_language=en " http://www.arasaac.org/index.php

The repeated lines you see in varnishlog are for every time your VCL code tries to unset or manipulate cookie value otherwise (during cleanup stage).

Varnish 4: how to purge cache with cookies

1 Answers