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