[Varnish] #941: beresp.ttl not honred when set in vcl_fetch
Varnish
varnish-bugs at varnish-cache.org
Mon Jun 27 12:12:34 CEST 2011
#941: beresp.ttl not honred when set in vcl_fetch
-------------------+--------------------------------------------------------
Reporter: david | Type: defect
Status: new | Priority: normal
Milestone: | Component: build
Version: 3.0.0 | Severity: normal
Keywords: |
-------------------+--------------------------------------------------------
Description changed by phk:
Old description:
> Hello,
>
> I opened a forum report on this, but haven't gotten an answer. At this
> point, I have performed enough troubleshooting to narrow this down to a
> bug in Varnish. I apologize if this is just a change of behavior from
> version 2 to 3, but I cannot find anything in the docs about this other
> than the removing of beresp.cacheable.
>
> When I set beresp.ttl to a value, it is simply not used. My testing shows
> that Varnish calculates an objects TTL based on two things:
> 1. backend Cache-Control header (max-age parameter in my case).
> 2. Default TTL passed to varnishd via -t run-time flag.
>
> beresp.ttl is not considered. I also attempted to arbitrarily set
> beresp.http.Cache-Control to something with a different max-age than the
> backend sent us. Varnish still uses the back-end's response regardless of
> my setting. If the back-end did not supply a Cache-Control header, then
> the default TTL is used.
>
> Let me know if you need more info than what is seen below.
>
> Regards,
> -david
>
> Here is my test bed:
>
> DAEMON_OPTS="-a :80 \
> -T :6082 \
> -f /etc/varnish/varnish.conf \
> -u varnish -g varnish \
> -s file,/var/nish/02/varnish.cache,22G \
> -s file,/var/nish/03/varnish.cache,22G \
> -s file,/var/nish/04/varnish.cache,22G \
> -s file,/var/nish/05/varnish.cache,22G \
> -s file,/var/nish/06/varnish.cache,22G \
> -h classic,800009 \
> -p session_linger=100 \
> -p ban_lurker_sleep=0.000001 \
> -p thread_pool_add_delay=1 \
> -p thread_pool_max=4000 \
> -p thread_pool_min=300 \
> -p thread_pools=4 \
> -p listen_depth=2048 \
> -p sess_workspace=65536 \
> -p shm_workspace=16384 \
> -p ping_interval=8 \
> -p cli_timeout=20 \
> -p lru_interval=30 \
> -p http_gzip_support=off \
> -p sess_timeout=5 \
> -p http_req_hdr_len=4096 \
> -p syslog_cli_traffic=off \
> -t 30000"
>
> This is my entire VCL:
> backend default {
> .host = "172.21.4.125";
> .port = "80";
> .connect_timeout = 10s;
> .first_byte_timeout = 35s;
> .between_bytes_timeout = 5s;
> }
>
> sub vcl_fetch {
> set beresp.ttl = 1000s;
> set beresp.http.X-WeAreHere = "here we are";
> return(deliver);
> }
>
> This is the curl command I used:
> time curl -x bil1-varn01:80 http://www.livejournal.com/
>
> This is the snippet from varnishlog that is this request (notice the TTL
> of 30000):
> 16 StatSess c 172.21.4.18 53230 0 1 0 0 0 0 0 0
> 17 BackendClose - prodtest
> 17 BackendOpen b prodtest 172.21.4.182 33060 172.21.4.125 80
> 17 TxRequest b GET
> 17 TxURL b http://www.livejournal.com/
> 17 TxProtocol b HTTP/1.1
> 17 TxHeader b User-Agent: curl/7.15.5 (i686-redhat-linux-gnu)
> libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
> 17 TxHeader b Host: www.livejournal.com
> 17 TxHeader b Pragma: no-cache
> 17 TxHeader b Accept: */*
> 17 TxHeader b Proxy-Connection: Keep-Alive
> 17 TxHeader b X-Forwarded-For: 172.21.0.32
> 17 TxHeader b X-Varnish: 1205010972
> 17 RxProtocol b HTTP/1.1
> 17 RxStatus b 200
> 17 RxResponse b OK
> 17 RxHeader b Date: Mon, 20 Jun 2011 20:15:57 GMT
> 17 RxHeader b Server: Apache/2.2.3 (CentOS)
> 17 RxHeader b X-AWS-Id: ws50
> 17 RxHeader b Cache-Control: private, proxy-revalidate
> 17 RxHeader b ETag: "da94603f920ddeddbba618fa22ade7ad"
> 17 RxHeader b Content-length: 47178
> 17 RxHeader b Content-Type: text/html; charset=utf-8
> 17 RxHeader b Content-Language: en
> 17 Fetch_Body b 4 0 1
> 17 Length b 47178
> 17 BackendReuse b prodtest
> 16 SessionOpen c 172.21.0.32 53590 :80
> 16 ReqStart c 172.21.0.32 53590 1205010972
> 16 RxRequest c GET
> 16 RxURL c http://www.livejournal.com/
> 16 RxProtocol c HTTP/1.1
> 16 RxHeader c User-Agent: curl/7.15.5 (i686-redhat-linux-gnu)
> libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
> 16 RxHeader c Host: www.livejournal.com
> 16 RxHeader c Pragma: no-cache
> 16 RxHeader c Accept: */*
> 16 RxHeader c Proxy-Connection: Keep-Alive
> 16 VCL_call c recv lookup
> 16 VCL_call c hash
> 16 Hash c http://www.livejournal.com/
> 16 Hash c www.livejournal.com
> 16 VCL_return c hash
> 16 VCL_call c miss fetch
> 16 Backend c 17 prodtest prodtest
> 16 TTL c 1205010972 RFC 30000 1308600958 0 0 0 0
> 16 VCL_call c fetch deliver
> 16 ObjProtocol c HTTP/1.1
> 16 ObjResponse c OK
> 16 ObjHeader c Date: Mon, 20 Jun 2011 20:15:57 GMT
> 16 ObjHeader c Server: Apache/2.2.3 (CentOS)
> 16 ObjHeader c X-AWS-Id: ws50
> 16 ObjHeader c Cache-Control: private, proxy-revalidate
> 16 ObjHeader c ETag: "da94603f920ddeddbba618fa22ade7ad"
> 16 ObjHeader c Content-Type: text/html; charset=utf-8
> 16 ObjHeader c Content-Language: en
> 16 ObjHeader c X-WeAreHere: here we are
> 16 VCL_call c deliver deliver
> 16 TxProtocol c HTTP/1.1
> 16 TxStatus c 200
> 16 TxResponse c OK
> 16 TxHeader c Server: Apache/2.2.3 (CentOS)
> 16 TxHeader c X-AWS-Id: ws50
> 16 TxHeader c Cache-Control: private, proxy-revalidate
> 16 TxHeader c ETag: "da94603f920ddeddbba618fa22ade7ad"
> 16 TxHeader c Content-Type: text/html; charset=utf-8
> 16 TxHeader c Content-Language: en
> 16 TxHeader c X-WeAreHere: here we are
> 16 TxHeader c Content-Length: 47178
> 16 TxHeader c Accept-Ranges: bytes
> 16 TxHeader c Date: Mon, 20 Jun 2011 20:15:57 GMT
> 16 TxHeader c X-Varnish: 1205010972
> 16 TxHeader c Age: 0
> 16 TxHeader c Via: 1.1 varnish
> 16 TxHeader c Connection: keep-alive
> 16 Length c 47178
> 16 ReqEnd c 1205010972 1308600957.437629938 1308600957.725367069
> 0.000030994 0.286793947 0.000943184
> 16 Debug c herding
> 16 SessionClose c no request
New description:
Hello,
I opened a forum report on this, but haven't gotten an answer. At this
point, I have performed enough troubleshooting to narrow this down to a
bug in Varnish. I apologize if this is just a change of behavior from
version 2 to 3, but I cannot find anything in the docs about this other
than the removing of beresp.cacheable.
When I set beresp.ttl to a value, it is simply not used. My testing shows
that Varnish calculates an objects TTL based on two things:
1. backend Cache-Control header (max-age parameter in my case).
2. Default TTL passed to varnishd via -t run-time flag.
beresp.ttl is not considered. I also attempted to arbitrarily set
beresp.http.Cache-Control to something with a different max-age than the
backend sent us. Varnish still uses the back-end's response regardless of
my setting. If the back-end did not supply a Cache-Control header, then
the default TTL is used.
Let me know if you need more info than what is seen below.
Regards,
-david
Here is my test bed:
{{{
DAEMON_OPTS="-a :80 \
-T :6082 \
-f /etc/varnish/varnish.conf \
-u varnish -g varnish \
-s file,/var/nish/02/varnish.cache,22G \
-s file,/var/nish/03/varnish.cache,22G \
-s file,/var/nish/04/varnish.cache,22G \
-s file,/var/nish/05/varnish.cache,22G \
-s file,/var/nish/06/varnish.cache,22G \
-h classic,800009 \
-p session_linger=100 \
-p ban_lurker_sleep=0.000001 \
-p thread_pool_add_delay=1 \
-p thread_pool_max=4000 \
-p thread_pool_min=300 \
-p thread_pools=4 \
-p listen_depth=2048 \
-p sess_workspace=65536 \
-p shm_workspace=16384 \
-p ping_interval=8 \
-p cli_timeout=20 \
-p lru_interval=30 \
-p http_gzip_support=off \
-p sess_timeout=5 \
-p http_req_hdr_len=4096 \
-p syslog_cli_traffic=off \
-t 30000"
This is my entire VCL:
backend default {
.host = "172.21.4.125";
.port = "80";
.connect_timeout = 10s;
.first_byte_timeout = 35s;
.between_bytes_timeout = 5s;
}
sub vcl_fetch {
set beresp.ttl = 1000s;
set beresp.http.X-WeAreHere = "here we are";
return(deliver);
}
This is the curl command I used:
time curl -x bil1-varn01:80 http://www.livejournal.com/
This is the snippet from varnishlog that is this request (notice the TTL
of 30000):
16 StatSess c 172.21.4.18 53230 0 1 0 0 0 0 0 0
17 BackendClose - prodtest
17 BackendOpen b prodtest 172.21.4.182 33060 172.21.4.125 80
17 TxRequest b GET
17 TxURL b http://www.livejournal.com/
17 TxProtocol b HTTP/1.1
17 TxHeader b User-Agent: curl/7.15.5 (i686-redhat-linux-gnu)
libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
17 TxHeader b Host: www.livejournal.com
17 TxHeader b Pragma: no-cache
17 TxHeader b Accept: */*
17 TxHeader b Proxy-Connection: Keep-Alive
17 TxHeader b X-Forwarded-For: 172.21.0.32
17 TxHeader b X-Varnish: 1205010972
17 RxProtocol b HTTP/1.1
17 RxStatus b 200
17 RxResponse b OK
17 RxHeader b Date: Mon, 20 Jun 2011 20:15:57 GMT
17 RxHeader b Server: Apache/2.2.3 (CentOS)
17 RxHeader b X-AWS-Id: ws50
17 RxHeader b Cache-Control: private, proxy-revalidate
17 RxHeader b ETag: "da94603f920ddeddbba618fa22ade7ad"
17 RxHeader b Content-length: 47178
17 RxHeader b Content-Type: text/html; charset=utf-8
17 RxHeader b Content-Language: en
17 Fetch_Body b 4 0 1
17 Length b 47178
17 BackendReuse b prodtest
16 SessionOpen c 172.21.0.32 53590 :80
16 ReqStart c 172.21.0.32 53590 1205010972
16 RxRequest c GET
16 RxURL c http://www.livejournal.com/
16 RxProtocol c HTTP/1.1
16 RxHeader c User-Agent: curl/7.15.5 (i686-redhat-linux-gnu)
libcurl/7.15.5 OpenSSL/0.9.8b zlib/1.2.3 libidn/0.6.5
16 RxHeader c Host: www.livejournal.com
16 RxHeader c Pragma: no-cache
16 RxHeader c Accept: */*
16 RxHeader c Proxy-Connection: Keep-Alive
16 VCL_call c recv lookup
16 VCL_call c hash
16 Hash c http://www.livejournal.com/
16 Hash c www.livejournal.com
16 VCL_return c hash
16 VCL_call c miss fetch
16 Backend c 17 prodtest prodtest
16 TTL c 1205010972 RFC 30000 1308600958 0 0 0 0
16 VCL_call c fetch deliver
16 ObjProtocol c HTTP/1.1
16 ObjResponse c OK
16 ObjHeader c Date: Mon, 20 Jun 2011 20:15:57 GMT
16 ObjHeader c Server: Apache/2.2.3 (CentOS)
16 ObjHeader c X-AWS-Id: ws50
16 ObjHeader c Cache-Control: private, proxy-revalidate
16 ObjHeader c ETag: "da94603f920ddeddbba618fa22ade7ad"
16 ObjHeader c Content-Type: text/html; charset=utf-8
16 ObjHeader c Content-Language: en
16 ObjHeader c X-WeAreHere: here we are
16 VCL_call c deliver deliver
16 TxProtocol c HTTP/1.1
16 TxStatus c 200
16 TxResponse c OK
16 TxHeader c Server: Apache/2.2.3 (CentOS)
16 TxHeader c X-AWS-Id: ws50
16 TxHeader c Cache-Control: private, proxy-revalidate
16 TxHeader c ETag: "da94603f920ddeddbba618fa22ade7ad"
16 TxHeader c Content-Type: text/html; charset=utf-8
16 TxHeader c Content-Language: en
16 TxHeader c X-WeAreHere: here we are
16 TxHeader c Content-Length: 47178
16 TxHeader c Accept-Ranges: bytes
16 TxHeader c Date: Mon, 20 Jun 2011 20:15:57 GMT
16 TxHeader c X-Varnish: 1205010972
16 TxHeader c Age: 0
16 TxHeader c Via: 1.1 varnish
16 TxHeader c Connection: keep-alive
16 Length c 47178
16 ReqEnd c 1205010972 1308600957.437629938 1308600957.725367069
0.000030994 0.286793947 0.000943184
16 Debug c herding
16 SessionClose c no request
}}}
--
--
Ticket URL: <http://www.varnish-cache.org/trac/ticket/941#comment:2>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list