Strange Issue with cache and logged in users

Pinakee BIswas pinakee at waltzz.com
Thu May 26 16:40:19 CEST 2016


Hi Guillaume,

Thanks for your response.

I did some more testing and it seems the pages are somehow getting 
cached irrespective of whatever logic I have put in the 
vcl_backend_response:

sub vcl_backend_response {
     # Happens after we have read the response headers from the backend.
     #
     # Here you clean the response headers, removing silly Set-Cookie 
headers
     # and other mistakes your backend does.
     if (bereq.method == "GET") {
                 set beresp.do_esi = true;
         if ((beresp.http.Set-Cookie !~ "loggedin_user=") &&
                 (beresp.http.Set-Cookie !~ "sessionid=") &&
                 (bereq.http.Cookie !~ "sessionid=") &&
                 (bereq.http.Cookie !~ "loggedin_user=") &&
                 (bereq.url !~ "^/esi")) {
                 #unset beresp.http.Set-Cookie;
                 set beresp.uncacheable = false;
                 return(deliver);
         }
     }
}

Regarding the faulty request, Following are two requests for the same 
URL - /heels/ - one when the user was logged in and another when the 
user had logged out. The second one (when the user was logged out) is 
the faulty one as the user is still seeing the data when he was logged in.

*_For the logged in User:_*

*   << BeReq    >> 65542
-   Begin          bereq 65541 pass
-   Timestamp      Start: 1464273298.494530 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /heels/
-   BereqProtocol  HTTP/1.0
-   BereqHeader    X-CLIENT-COUNTRY: IN
-   BereqHeader    Host: varnish_staging
-   BereqHeader    Cache-Control: max-age=0
-   BereqHeader    Accept: 
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   BereqHeader    Upgrade-Insecure-Requests: 1
-   BereqHeader    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 
10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 
Safari/537.36
-   BereqHeader    Referer: http://test.jivaana.in/juttis/
-   BereqHeader    Accept-Encoding: gzip, deflate, sdch
-   BereqHeader    Accept-Language: en-US,en;q=0.8
-   BereqHeader    Cookie: 
_xsrf=2|f25d8caf|ffacf1c86b71827915f94aed8e9aeace|1462920275; 
jivaana_country=IN; pagemap=0,0,0,0,0,1,0'; 
mp_774636c1ed2371eaf99455f71871069c_mixpanel=%7B%22distinct_id%22%3A%20%221518b8ba6c314b-04bd3d4-6b1b237b-100200-1518b8ba6c428a%22%2C%22%24i
-   BereqHeader    X-Forwarded-For: 127.0.0.1
-   BereqHeader    X-Varnish: 65542
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    21 boot.uwsgi 127.0.0.1 7090 127.0.0.1 57783
-   Timestamp      Bereq: 1464273298.494747 0.000217 0.000217
-   Timestamp      Beresp: 1464273298.507940 0.013410 0.013193
-   BerespProtocol HTTP/1.0
-   BerespStatus   200
-   BerespReason   OK
-   BerespHeader   Content-Length: 257701
-   BerespHeader   Expires: Thu, 26 May 2016 14:39:55 GMT
-   BerespHeader   Vary: X-CLIENT-COUNTRY, Cookie
-   BerespHeader   X-CLIENT-COUNTRY: IN
-   BerespHeader   Last-Modified: Thu, 26 May 2016 14:34:55 GMT
-   BerespHeader   Cache-Control: max-age=300
-   BerespHeader   Date: Thu, 26 May 2016 14:34:58 GMT
-   BerespHeader   X-Frame-Options: SAMEORIGIN
-   BerespHeader   Content-Type: text/html; charset=utf-8
-   BerespHeader   Set-Cookie:  jivaana_num_basket_items=; expires=Thu, 
01-Jan-1970 00:00:00 GMT; Max-Age=0; Path=/
-   TTL            RFC 300 10 -1 1464273299 1464273299 1464273298 
1464273595 300
-   VCL_call       BACKEND_RESPONSE
-   TTL            VCL 120 10 0 1464273299
-   VCL_return     deliver
-   Storage        malloc Transient
-   ObjProtocol    HTTP/1.0
-   ObjStatus      200
-   ObjReason      OK
-   ObjHeader      Content-Length: 257701
-   ObjHeader      Expires: Thu, 26 May 2016 14:39:55 GMT
-   ObjHeader      Vary: X-CLIENT-COUNTRY, Cookie
-   ObjHeader      X-CLIENT-COUNTRY: IN
-   ObjHeader      Last-Modified: Thu, 26 May 2016 14:34:55 GMT
-   ObjHeader      Cache-Control: max-age=300
-   ObjHeader      Date: Thu, 26 May 2016 14:34:58 GMT
-   ObjHeader      X-Frame-Options: SAMEORIGIN
-   ObjHeader      Content-Type: text/html; charset=utf-8
-   ObjHeader      Set-Cookie:  jivaana_num_basket_items=; expires=Thu, 
01-Jan-1970 00:00:00 GMT; Max-Age=0; Path=/
-   Fetch_Body     3 length stream
-   BackendClose   21 boot.uwsgi
-   Timestamp      BerespBody: 1464273298.512453 0.017923 0.004513
-   Length         257701
-   BereqAcct      1396 0 1396 415 257701 258116
-   End

*   << Request  >> 65541
-   Begin          req 65540 rxreq
-   Timestamp      Start: 1464273298.494400 0.000000 0.000000
-   Timestamp      Req: 1464273298.494400 0.000000 0.000000
-   ReqStart       127.0.0.1 43438
-   ReqMethod      GET
-   ReqURL         /heels/
-   ReqProtocol    HTTP/1.0
-   ReqHeader      X-CLIENT-COUNTRY: IN
-   ReqHeader      Host: varnish_staging
-   ReqHeader      Connection: close
-   ReqHeader      Cache-Control: max-age=0
-   ReqHeader      Accept: 
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 
10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 
Safari/537.36
-   ReqHeader      Referer: http://test.jivaana.in/juttis/
-   ReqHeader      Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Language: en-US,en;q=0.8
-   ReqHeader      Cookie: 
_xsrf=2|f25d8caf|ffacf1c86b71827915f94aed8e9aeace|1462920275; 
jivaana_country=IN; pagemap=0,0,0,0,0,1,0'; 
mp_774636c1ed2371eaf99455f71871069c_mixpanel=%7B%22distinct_id%22%3A%20%221518b8ba6c314b-04bd3d4-6b1b237b-100200-1518b8ba6c428a%22%2C%22%24i
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_call       RECV
-   VCL_return     pass
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 65542 pass
-   Timestamp      Fetch: 1464273298.508162 0.013762 0.013762
-   RespProtocol   HTTP/1.0
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Content-Length: 257701
-   RespHeader     Expires: Thu, 26 May 2016 14:39:55 GMT
-   RespHeader     Vary: X-CLIENT-COUNTRY, Cookie
-   RespHeader     X-CLIENT-COUNTRY: IN
-   RespHeader     Last-Modified: Thu, 26 May 2016 14:34:55 GMT
-   RespHeader     Cache-Control: max-age=300
-   RespHeader     Date: Thu, 26 May 2016 14:34:58 GMT
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Set-Cookie:  jivaana_num_basket_items=; expires=Thu, 
01-Jan-1970 00:00:00 GMT; Max-Age=0; Path=/
-   RespProtocol   HTTP/1.1
-   RespHeader     X-Varnish: 65541
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1464273298.508196 0.013796 0.000034
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1464273298.512479 0.018080 0.004284
-   ReqAcct        1369 0 1369 503 257701 258204
-   End

*   << Session  >> 65540
-   Begin          sess 0 HTTP/1
-   SessOpen       127.0.0.1 43438 0.0.0.0:9003 127.0.0.1 9003 
1464273298.494343 20
-   Link           req 65541 rxreq
-   SessClose      RESP_CLOSE 0.018
-   End

_*For the logged out user:*_

*   << BeReq    >> 32788
-   Begin          bereq 32787 fetch
-   Timestamp      Start: 1464273406.124375 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /heels/
-   BereqProtocol  HTTP/1.0
-   BereqHeader    X-CLIENT-COUNTRY: IN
-   BereqHeader    Host: varnish_staging
-   BereqHeader    Accept: 
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   BereqHeader    Upgrade-Insecure-Requests: 1
-   BereqHeader    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 
10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 
Safari/537.36
-   BereqHeader    Referer: http://test.jivaana.in/home
-   BereqHeader    Accept-Language: en-US,en;q=0.8
-   BereqHeader    X-Forwarded-For: 127.0.0.1
-   BereqHeader    Accept-Encoding: gzip
-   BereqProtocol  HTTP/1.1
-   BereqHeader    X-Varnish: 32788
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    21 boot.uwsgi 127.0.0.1 7090 127.0.0.1 57794
-   Timestamp      Bereq: 1464273406.124744 0.000369 0.000369
-   Timestamp      Beresp: 1464273406.137721 0.013346 0.012977
-   BerespProtocol HTTP/1.1
-   BerespStatus   200
-   BerespReason   OK
-   BerespHeader   Content-Length: 257701
-   BerespHeader   Expires: Thu, 26 May 2016 14:39:55 GMT
-   BerespHeader   Vary: X-CLIENT-COUNTRY, Cookie
-   BerespHeader   X-CLIENT-COUNTRY: IN
-   BerespHeader   Last-Modified: Thu, 26 May 2016 14:34:55 GMT
-   BerespHeader   Cache-Control: max-age=300
-   BerespHeader   Date: Thu, 26 May 2016 14:36:46 GMT
-   BerespHeader   X-Frame-Options: SAMEORIGIN
-   BerespHeader   Content-Type: text/html; charset=utf-8
-   BerespHeader   Set-Cookie:  jivaana_num_basket_items=; expires=Thu, 
01-Jan-1970 00:00:00 GMT; Max-Age=0; Path=/
-   TTL            RFC 300 10 -1 1464273406 1464273406 1464273406 
1464273595 300
-   VCL_call       BACKEND_RESPONSE
-   BerespUnset    Set-Cookie:  jivaana_num_basket_items=; expires=Thu, 
01-Jan-1970 00:00:00 GMT; Max-Age=0; Path=/
-   VCL_Log        Caching the url : **********************/heels/
-   VCL_return     deliver
-   Storage        file s0
-   ObjProtocol    HTTP/1.1
-   ObjStatus      200
-   ObjReason      OK
-   ObjHeader      Content-Length: 257701
-   ObjHeader      Expires: Thu, 26 May 2016 14:39:55 GMT
-   ObjHeader      Vary: X-CLIENT-COUNTRY, Cookie
-   ObjHeader      X-CLIENT-COUNTRY: IN
-   ObjHeader      Last-Modified: Thu, 26 May 2016 14:34:55 GMT
-   ObjHeader      Cache-Control: max-age=300
-   ObjHeader      Date: Thu, 26 May 2016 14:36:46 GMT
-   ObjHeader      X-Frame-Options: SAMEORIGIN
-   ObjHeader      Content-Type: text/html; charset=utf-8
-   Fetch_Body     3 length stream
-   BackendReuse   21 boot.uwsgi
-   Timestamp      BerespBody: 1464273406.139210 0.014835 0.001489
-   Length         257701
-   BereqAcct      457 0 457 415 257701 258116
-   End

*   << Request  >> 32787
-   Begin          req 32786 rxreq
-   Timestamp      Start: 1464273406.124217 0.000000 0.000000
-   Timestamp      Req: 1464273406.124217 0.000000 0.000000
-   ReqStart       127.0.0.1 43449
-   ReqMethod      GET
-   ReqURL         /heels/
-   ReqProtocol    HTTP/1.0
-   ReqHeader      X-CLIENT-COUNTRY: IN
-   ReqHeader      Host: varnish_staging
-   ReqHeader      Connection: close
-   ReqHeader      Accept: 
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 
10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 
Safari/537.36
-   ReqHeader      Referer: http://test.jivaana.in/home
-   ReqHeader      Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Language: en-US,en;q=0.8
-   ReqHeader      Cookie: 
_xsrf=2|f25d8caf|ffacf1c86b71827915f94aed8e9aeace|1462920275; 
jivaana_country=IN; pagemap=0,0,0,0,0,1,0'; _gat=1; 
csrftoken=PFm9lTAeFcQLIHY2UsUjkuO73R1GVaxn; 
_ga=GA1.2.886266615.1446454138; 
mp_774636c1ed2371eaf99455f71871069c_mixpanel=%7B%22disti
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_call       RECV
-   ReqUnset       Cookie: 
_xsrf=2|f25d8caf|ffacf1c86b71827915f94aed8e9aeace|1462920275; 
jivaana_country=IN; pagemap=0,0,0,0,0,1,0'; _gat=1; 
csrftoken=PFm9lTAeFcQLIHY2UsUjkuO73R1GVaxn; 
_ga=GA1.2.886266615.1446454138; 
mp_774636c1ed2371eaf99455f71871069c_mixpanel=%7B%22disti
-   VCL_return     hash
-   ReqUnset       Accept-Encoding: gzip, deflate, sdch
-   ReqHeader      Accept-Encoding: gzip
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 32788 fetch
-   Timestamp      Fetch: 1464273406.138165 0.013947 0.013947
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Content-Length: 257701
-   RespHeader     Expires: Thu, 26 May 2016 14:39:55 GMT
-   RespHeader     Vary: X-CLIENT-COUNTRY, Cookie
-   RespHeader     X-CLIENT-COUNTRY: IN
-   RespHeader     Last-Modified: Thu, 26 May 2016 14:34:55 GMT
-   RespHeader     Cache-Control: max-age=300
-   RespHeader     Date: Thu, 26 May 2016 14:36:46 GMT
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     X-Varnish: 32787
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1464273406.138211 0.013993 0.000046
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1464273406.139451 0.015234 0.001240
-   ReqAcct        1119 0 1119 405 257701 258106
-   End

*   << Session  >> 32786
-   Begin          sess 0 HTTP/1
-   SessOpen       127.0.0.1 43449 0.0.0.0:9003 127.0.0.1 9003 
1464273406.124096 16
-   Link           req 32787 rxreq
-   SessClose      RESP_CLOSE 0.016
-   End


Thanks,
Pinakee


On 26/05/16 7:58 pm, Guillaume Quintard wrote:
> Are you able to isolate the faulty request in varnishlog? The one that 
> should be passed and isn't?
>
> -- 
> Guillaume Quintard
>
> On Thu, May 26, 2016 at 4:07 PM, Pinakee BIswas <pinakee at waltzz.com 
> <mailto:pinakee at waltzz.com>> wrote:
>
>     Further adding the observations with the following scenario:
>
>      1. Visit URL A-not-loggedin
>      2. Visit URL B-not-loggedin
>      3. User logs in
>      4. Visit URL A after logging in - varnish is serving the page -
>         A-not-loggedin
>      5. Visit URL B after logging in - varnish is serving the page
>         B-not-loggedin
>
>     This means Varnish is serving the pages just visited (till cache
>     expiry) irrespective of the fact that the page is being fetched
>     from backend and that there is a pass in vcl_recv.
>
>     I am unable to understand the above mentioned behavior - the VCL
>     logic I used is simple as mentioned in the mail below.
>
>     Regards,
>
>     Pinakee
>
>
>     On 26/05/16 6:24 pm, Pinakee BIswas wrote:
>>     Hi,
>>
>>     I am facing a strange problem with Varnish cache. Ours is an
>>     ecommerce site wherein users can visit with or without logging
>>     in. I have written the VCL to unset cookies when user not logged in.
>>
>>     The scenario is user logs in and then logs out. When the user
>>     logs out, Varnish is still delivering logged in pages to the user
>>     which is strange as the requests for logged in users go all the
>>     way to the backend and the pages are not supposed to get cached.
>>     I have been looking into this since quite some time and still not
>>     able to figure out the reason.
>>
>>     Would appreciate any help.
>>
>>     Thanks,
>>
>>     Pinakee
>>
>>     PFA the output from varnishlog.
>>
>>     Following is the VCL code:
>>
>>     sub vcl_recv {
>>         # Happens before we check if we have this in cache already.
>>         #
>>         # Typically you clean up the request here, removing cookies
>>     you don't need,
>>         # rewriting the request, etc.
>>         set req.backend_hint = uwsgi;
>>
>>        if (req.method == "GET") {
>>             if ((req.http.Cookie !~ "sessionid=") &&
>>                 (req.http.Cookie !~ "loggedin_user=") &&
>>                 (req.url !~ "^/esi")) {
>>                     unset req.http.cookie; # strip the cookies - we
>>     don't need them
>>             }
>>         }
>>     }
>>
>>     sub vcl_backend_response {
>>         # Happens after we have read the response headers from the
>>     backend.
>>         #
>>         # Here you clean the response headers, removing silly
>>     Set-Cookie headers
>>         # and other mistakes your backend does.
>>         if (bereq.method == "GET") {
>>                     set beresp.do_esi = true;
>>             if ((beresp.http.Set-Cookie !~ "jivaana_user=") &&
>>                     (beresp.http.Set-Cookie !~ "sessionid=") &&
>>                     (bereq.http.Cookie !~ "sessionid=") &&
>>                     (bereq.http.Cookie !~ "jivaana_user=") &&
>>                     (bereq.url !~ "^/product/addtobasket")) {
>>                     #unset beresp.http.Set-Cookie;
>>                     set beresp.uncacheable = false;
>>                     return(deliver);
>>             }
>>         }
>>     }
>>
>
>
>     _______________________________________________
>     varnish-misc mailing list
>     varnish-misc at varnish-cache.org <mailto:varnish-misc at varnish-cache.org>
>     https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20160526/27546999/attachment-0001.html>


More information about the varnish-misc mailing list