Hello, Varnish folks! I am currently in the process of testing the ESI
features of Varnish. I have discovered that if I place more than one
<esi:inclide> on a document, any includes beyond the first are inserted
to the cache, but never hit on subsequent requests. I have tried to
determine if this is caused by something in my configuration but have
been unable to locate anything. I have distilled my test case down to
something which ought to be reproducible.
We are running varnish-trunk, latest revision within a week or so.
ESI is being triggered off the filename, for simplicity sake, as such:
sub vcl_fetch {
remove obj.http.Set-Cookie;
if (req.url ~ "esi\.html$") {
esi;
}
}
varnish is being tested by several users on the server simultaneously,
using different non-privileged usernames and instance names (via -n).
See attached:
1) varnish_esi_case.txt, showing the contents of the source files,
detailed headers for all objects. Demonstrates that on two subsequent
requests, the max-age on the second include is not honored
2) varnish_varnishlog_output.txt, showing the output of varnishlog
(excliding ping/PONG) though a purge, and then both requests to the
ESI-enabled document.
An observation, which could easily be a mis-correlation: second and
subsequent requests for esi fragments are logged with an 'XID' of '0'. I
do not know if this is intentional or perhaps indicative of the
underlying problem.
Thanks for any insight you can provide!
--
JT Justman
End Point Corporation
http://www.endpoint.com
$ cat cgi-bin/date-5.cgi
#!/usr/local/bin/perl
use DateTime;
print "Content-Type: text/html; charset=iso-8859-1\nCache-Control:
max-age=5\n\n";
print DateTime->now();
print "\n";
$ ./date-5.cgi
Content-Type: text/html; charset=iso-8859-1
Cache-Control: max-age=5
2008-05-09T18:01:05
$ ./date-20.cgi
Content-Type: text/html; charset=iso-8859-1
Cache-Control: max-age=20
2008-05-09T18:01:12
$ lwp-request -U -s -e http://localhost:9138/cgi-bin/date-20.cgi
GET http://localhost:9138/cgi-bin/date-20.cgi
User-Agent: lwp-request/2.08
200 OK
Cache-Control: max-age=20
Connection: close
Date: Fri, 09 May 2008 18:02:31 GMT
Via: 1.1 varnish
Age: 0
Server: Apache
Content-Length: 20
Content-Type: text/html; charset=iso-8859-1
Client-Date: Fri, 09 May 2008 18:02:30 GMT
Client-Peer: 127.0.0.1:9138
Client-Response-Num: 1
P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT STA PRE POL CUR ADMa
PSAo PSDo IVAo IVDo CONo OUR", policyref="http://localhost:9138/w3c/p3p.xml";
X-Varnish: 1887710906
2008-05-09T18:02:31
$ lwp-request -U -s -e http://localhost:9138/cgi-bin/date-5.cgi
GET http://localhost:9138/cgi-bin/date-5.cgi
User-Agent: lwp-request/2.08
200 OK
Cache-Control: max-age=5
Connection: close
Date: Fri, 09 May 2008 18:03:13 GMT
Via: 1.1 varnish
Age: 0
Server: Apache
Content-Length: 20
Content-Type: text/html; charset=iso-8859-1
Client-Date: Fri, 09 May 2008 18:03:13 GMT
Client-Peer: 127.0.0.1:9138
Client-Response-Num: 1
P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT STA PRE POL CUR ADMa
PSAo PSDo IVAo IVDo CONo OUR", policyref="http://localhost:9138/w3c/p3p.xml";
X-Varnish: 1887710907
2008-05-09T18:03:13
$ cat html/test_esi.html
<html>
<body>
This document will use the default TTL.<br />
<br/>
Here is an ESI include with a five second timeout: <esi:include
src="/cgi-bin/date-5.cgi" />
<br/>
Here is an ESI include with a twenty second timeout: <esi:include
src="/cgi-bin/date-20.cgi" />
</body>
$ lwp-request -U -s -e http://localhost:9138/test_esi.html
GET http://localhost:9138/test_esi.html
User-Agent: lwp-request/2.08
200 OK
Connection: close
Date: Fri, 09 May 2008 18:16:12 GMT
Via: 1.1 varnish
Age: 0
ETag: "cc135-10d-18c031c0"
Server: Apache
Content-Type: text/html; charset=iso-8859-1
Last-Modified: Fri, 09 May 2008 18:09:19 GMT
Client-Date: Fri, 09 May 2008 18:16:12 GMT
Client-Peer: 127.0.0.1:9138
Client-Response-Num: 1
Client-Transfer-Encoding: chunked
P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT STA PRE POL CUR ADMa
PSAo PSDo IVAo IVDo CONo OUR", policyref="http://localhost:9138/w3c/p3p.xml";
X-Varnish: 1887710915
<html>
<body>
This document will use the default TTL.<br />
<br/>
Here is an ESI include with a five second timeout: 2008-05-09T18:16:12
<br/>
Here is an ESI include with a twenty second timeout: 2008-05-09T18:16:12
</body>
$ lwp-request -U -s -e http://localhost:9138/test_esi.html
GET http://localhost:9138/test_esi.html
User-Agent: lwp-request/2.08
200 OK
Connection: close
Date: Fri, 09 May 2008 18:16:14 GMT
Via: 1.1 varnish
Age: 2
ETag: "cc135-10d-18c031c0"
Server: Apache
Content-Type: text/html; charset=iso-8859-1
Last-Modified: Fri, 09 May 2008 18:09:19 GMT
Client-Date: Fri, 09 May 2008 18:16:14 GMT
Client-Peer: 127.0.0.1:9138
Client-Response-Num: 1
Client-Transfer-Encoding: chunked
P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT STA PRE POL CUR ADMa
PSAo PSDo IVAo IVDo CONo OUR", policyref="http://localhost:9138/w3c/p3p.xml";
X-Varnish: 1887710916 1887710915
<html>
<body>
This document will use the default TTL.<br />
<br/>
Here is an ESI include with a five second timeout: 2008-05-09T18:16:12
<br/>
Here is an ESI include with a twenty second timeout: 2008-05-09T18:16:14
</body>
NOT: PURGE EVERYTHING
0 CLI - Rd url.purge .+
0 CLI - Wr 0 200 PURGE .+
NOTE: BEGIN FIRST REQUEST
21 SessionOpen c 127.0.0.1 49046
21 Debug c "Parse: 269 <<html>%0a<body>%0aThis document will use the
default TTL.<br />%0a<br/>%0aHere is an ESI include with a five second timeout:
<esi:include src="/cgi-bin/date-5.cgi" />%0a<br/>%0aHere is an ESI include with
a twenty second timeout: <esi:include src="/cgi-bi"
21 Debug c "Element: clos=0 [html]"
21 Debug c "Element: clos=0 [body]"
21 Debug c "Element: clos=0 [br /]"
21 Debug c "Element: clos=0 [br/]"
21 Debug c "Element: clos=0 [esi:include src="/cgi-bin/date-5.cgi" /]"
21 Debug c "AddVer: 117 <<html>%0a<body>%0aThis document will use the
default TTL.<br />%0a<br/>%0aHere is an ESI include with a five second timeout:
>"
0 Debug - "Incl " src="/cgi-bin/date-5.cgi" ""
21 Debug c "AddBit: 117 <<html>%0a<body>%0aThis document will use the
default TTL.<br />%0a<br/>%0aHere is an ESI include with a five second timeout:
>"
0 Debug - "<src> -> </cgi-bin/date-5.cgi>"
21 Debug c "Element: clos=0 [br/]"
21 Debug c "Element: clos=0 [esi:include src="/cgi-bin/date-20.cgi"
/]"
21 Debug c "AddVer: 60 <%0a<br/>%0aHere is an ESI include with a
twenty second timeout: >"
0 Debug - "Incl " src="/cgi-bin/date-20.cgi" ""
21 Debug c "AddBit: 60 <%0a<br/>%0aHere is an ESI include with a
twenty second timeout: >"
0 Debug - "<src> -> </cgi-bin/date-20.cgi>"
21 Debug c "Element: clos=1 [body]"
21 Debug c "AddVer: 9 <%0a</body>%0a>"
21 Debug c "AddBit: 9 <%0a</body>%0a>"
21 ReqStart c 127.0.0.1 49046 1887710915
21 RxRequest c GET
21 RxURL c /test_esi.html
21 RxProtocol c HTTP/1.1
21 RxHeader c TE: deflate,gzip;q=0.3
21 RxHeader c Connection: TE, close
21 RxHeader c Host: localhost:9138
21 RxHeader c User-Agent: lwp-request/2.08
21 VCL_call c recv
21 VCL_return c lookup
21 VCL_call c hash
21 VCL_return c hash
21 VCL_call c miss
21 VCL_return c fetch
22 BackendClose b bcs
22 BackendOpen b bcs 127.0.0.1 36343 127.0.0.1 9138
22 TxRequest b GET
22 TxURL b /test_esi.html
22 TxProtocol b HTTP/1.1
22 TxHeader b Host: localhost:9138
22 TxHeader b User-Agent: lwp-request/2.08
22 TxHeader b X-Varnish: 1887710915
22 TxHeader b X-Forwarded-for: 127.0.0.1
22 RxProtocol b HTTP/1.1
22 RxStatus b 200
22 RxResponse b OK
22 RxHeader b Date: Fri, 09 May 2008 18:16:12 GMT
22 RxHeader b Server: Apache
22 RxHeader b Last-Modified: Fri, 09 May 2008 18:09:19 GMT
22 RxHeader b ETag: "cc135-10d-18c031c0"
22 RxHeader b Accept-Ranges: bytes
22 RxHeader b Content-Length: 269
22 RxHeader b P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
22 RxHeader b Content-Type: text/html; charset=iso-8859-1
21 ObjProtocol c HTTP/1.1
21 ObjStatus c 200
21 ObjResponse c OK
21 ObjHeader c Date: Fri, 09 May 2008 18:16:12 GMT
21 ObjHeader c Server: Apache
21 ObjHeader c Last-Modified: Fri, 09 May 2008 18:09:19 GMT
21 ObjHeader c ETag: "cc135-10d-18c031c0"
21 ObjHeader c P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
21 ObjHeader c Content-Type: text/html; charset=iso-8859-1
22 BackendReuse b bcs
21 TTL c 1887710915 RFC 120 1210356972 1210356972 0 0 0
21 VCL_call c fetch
21 VCL_return c insert
21 Length c 269
21 VCL_call c deliver
21 VCL_return c deliver
21 TxProtocol c HTTP/1.1
21 TxStatus c 200
21 TxResponse c OK
21 TxHeader c Server: Apache
21 TxHeader c Last-Modified: Fri, 09 May 2008 18:09:19 GMT
21 TxHeader c ETag: "cc135-10d-18c031c0"
21 TxHeader c P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
21 TxHeader c Content-Type: text/html; charset=iso-8859-1
21 TxHeader c Transfer-Encoding: chunked
21 TxHeader c Date: Fri, 09 May 2008 18:16:12 GMT
21 TxHeader c X-Varnish: 1887710915
21 TxHeader c Age: 0
21 TxHeader c Via: 1.1 varnish
21 TxHeader c Connection: close
21 VCL_call c recv
21 VCL_return c lookup
21 VCL_call c hash
21 VCL_return c hash
21 VCL_call c miss
21 VCL_return c fetch
22 TxRequest b GET
22 TxURL b /cgi-bin/date-5.cgi
22 TxProtocol b HTTP/1.1
22 TxHeader b Host: localhost:9138
22 TxHeader b User-Agent: lwp-request/2.08
22 TxHeader b X-Varnish: 1887710915
22 TxHeader b X-Forwarded-for: 127.0.0.1
22 RxProtocol b HTTP/1.1
22 RxStatus b 200
22 RxResponse b OK
22 RxHeader b Date: Fri, 09 May 2008 18:16:12 GMT
22 RxHeader b Server: Apache
22 RxHeader b Cache-Control: max-age=5
22 RxHeader b P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
22 RxHeader b Transfer-Encoding: chunked
22 RxHeader b Content-Type: text/html; charset=iso-8859-1
21 ObjProtocol c HTTP/1.1
21 ObjStatus c 200
21 ObjResponse c OK
21 ObjHeader c Date: Fri, 09 May 2008 18:16:12 GMT
21 ObjHeader c Server: Apache
21 ObjHeader c Cache-Control: max-age=5
21 ObjHeader c P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
21 ObjHeader c Content-Type: text/html; charset=iso-8859-1
22 BackendReuse b bcs
21 TTL c 1887710915 RFC 5 1210356972 1210356972 0 5 0
21 VCL_call c fetch
21 VCL_info c XID 1887710915: obj.prefetch (-30) less than ttl
(5.19188), ignored.
21 VCL_return c insert
21 Length c 20
21 VCL_call c deliver
21 VCL_return c deliver
21 ReqEnd c 1887710915 1210356972.365588903 1210356972.559792995
0.062586784 0.194151163 0.000052929
0 StatAddr - 127.0.0.1 0 90740 313 313 0 0 500 124534 167120
21 VCL_call c recv
21 VCL_return c lookup
21 VCL_call c hash
21 VCL_return c hash
21 VCL_call c miss
21 VCL_return c fetch
22 BackendClose b bcs
22 BackendOpen b bcs 127.0.0.1 36344 127.0.0.1 9138
22 TxRequest b GET
22 TxURL b /cgi-bin/date-20.cgi
22 TxProtocol b HTTP/1.1
22 TxHeader b Host: localhost:9138
22 TxHeader b User-Agent: lwp-request/2.08
22 TxHeader b X-Varnish: 0
22 TxHeader b X-Forwarded-for: 127.0.0.1
22 RxProtocol b HTTP/1.1
22 RxStatus b 200
22 RxResponse b OK
22 RxHeader b Date: Fri, 09 May 2008 18:16:12 GMT
22 RxHeader b Server: Apache
22 RxHeader b Cache-Control: max-age=20
22 RxHeader b P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
22 RxHeader b Transfer-Encoding: chunked
22 RxHeader b Content-Type: text/html; charset=iso-8859-1
21 ObjProtocol c HTTP/1.1
21 ObjStatus c 200
21 ObjResponse c OK
21 ObjHeader c Date: Fri, 09 May 2008 18:16:12 GMT
21 ObjHeader c Server: Apache
21 ObjHeader c Cache-Control: max-age=20
21 ObjHeader c P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
21 ObjHeader c Content-Type: text/html; charset=iso-8859-1
22 BackendReuse b bcs
21 TTL c 0 RFC 20 1210356972 1210356972 0 20 0
21 VCL_call c fetch
21 VCL_info c XID 0: obj.prefetch (-30) less than ttl (nan), ignored.
21 VCL_return c insert
21 Length c 20
21 VCL_call c deliver
21 VCL_return c deliver
21 ReqEnd c 0 1210356972.754462957 1210356972.754462957 0.194669962
0.000000000 0.000000000
0 StatAddr - 127.0.0.1 0 90740 313 313 0 0 501 124538 167140
21 ReqEnd c 0 1210356972.754494905 1210356972.754494905 0.000031948
0.000000000 0.000000000
0 StatAddr - 127.0.0.1 0 90740 313 313 0 0 501 124538 167140
21 SessionClose c Connection: close
NOTE: END OF FIRST REQUEST
21 StatSess c 127.0.0.1 49046 0 1 1 0 0 3 465 40
21 SessionOpen c 127.0.0.1 49047
21 ReqStart c 127.0.0.1 49047 1887710916
21 RxRequest c GET
21 RxURL c /test_esi.html
21 RxProtocol c HTTP/1.1
21 RxHeader c TE: deflate,gzip;q=0.3
21 RxHeader c Connection: TE, close
21 RxHeader c Host: localhost:9138
21 RxHeader c User-Agent: lwp-request/2.08
21 VCL_call c recv
21 VCL_return c lookup
21 VCL_call c hash
21 VCL_return c hash
21 Hit c 1887710915
21 VCL_call c hit
21 VCL_return c deliver
21 Length c 269
21 VCL_call c deliver
21 VCL_return c deliver
21 TxProtocol c HTTP/1.1
21 TxStatus c 200
21 TxResponse c OK
21 TxHeader c Server: Apache
21 TxHeader c Last-Modified: Fri, 09 May 2008 18:09:19 GMT
21 TxHeader c ETag: "cc135-10d-18c031c0"
21 TxHeader c P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
21 TxHeader c Content-Type: text/html; charset=iso-8859-1
21 TxHeader c Transfer-Encoding: chunked
21 TxHeader c Date: Fri, 09 May 2008 18:16:14 GMT
21 TxHeader c X-Varnish: 1887710916 1887710915
21 TxHeader c Age: 2
21 TxHeader c Via: 1.1 varnish
21 TxHeader c Connection: close
21 VCL_call c recv
21 VCL_return c lookup
21 VCL_call c hash
21 VCL_return c hash
21 Hit c 1887710915
21 VCL_call c hit
21 VCL_return c deliver
21 Length c 20
21 VCL_call c deliver
21 VCL_return c deliver
21 ReqEnd c 1887710916 1210356974.562180042 1210356974.562355995
0.064829111 0.000151873 0.000024080
0 StatAddr - 127.0.0.1 0 90742 314 314 0 0 501 125010 167160
21 VCL_call c recv
21 VCL_return c lookup
21 VCL_call c hash
21 VCL_return c hash
21 VCL_call c miss
21 VCL_return c fetch
22 BackendClose b bcs
22 BackendOpen b bcs 127.0.0.1 36345 127.0.0.1 9138
22 TxRequest b GET
22 TxURL b /cgi-bin/date-20.cgi
22 TxProtocol b HTTP/1.1
22 TxHeader b Host: localhost:9138
22 TxHeader b User-Agent: lwp-request/2.08
22 TxHeader b X-Varnish: 0
22 TxHeader b X-Forwarded-for: 127.0.0.1
22 RxProtocol b HTTP/1.1
22 RxStatus b 200
22 RxResponse b OK
22 RxHeader b Date: Fri, 09 May 2008 18:16:14 GMT
22 RxHeader b Server: Apache
22 RxHeader b Cache-Control: max-age=20
22 RxHeader b P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
22 RxHeader b Transfer-Encoding: chunked
22 RxHeader b Content-Type: text/html; charset=iso-8859-1
21 ObjProtocol c HTTP/1.1
21 ObjStatus c 200
21 ObjResponse c OK
21 ObjHeader c Date: Fri, 09 May 2008 18:16:14 GMT
21 ObjHeader c Server: Apache
21 ObjHeader c Cache-Control: max-age=20
21 ObjHeader c P3P: CP="IND NON DSP PHY ONL UNI FIN PUR COM INT DEM CNT
STA PRE POL CUR ADMa PSAo PSDo IVAo IVDo CONo OUR",
policyref="http://localhost:9138/w3c/p3p.xml";
21 ObjHeader c Content-Type: text/html; charset=iso-8859-1
22 BackendReuse b bcs
21 TTL c 0 RFC 20 1210356974 1210356974 0 20 0
21 VCL_call c fetch
21 VCL_info c XID 0: obj.prefetch (-30) less than ttl (nan), ignored.
21 VCL_return c insert
21 Length c 20
21 VCL_call c deliver
21 VCL_return c deliver
21 ReqEnd c 0 1210356974.761723995 1210356974.761723995 0.199368000
0.000000000 0.000000000
0 StatAddr - 127.0.0.1 0 90742 314 314 0 0 502 125014 167180
21 ReqEnd c 0 1210356974.761764050 1210356974.761764050 0.000040054
0.000000000 0.000000000
0 StatAddr - 127.0.0.1 0 90742 314 314 0 0 502 125014 167180
21 SessionClose c Connection: close
21 StatSess c 127.0.0.1 49047 0 1 1 0 0 1 476 40
0 ExpPick - 1887710915 ttl
0 VCL_call - timeout
0 VCL_return - discard
0 ExpKill - 1887710915 0
0 ExpPick - 0 ttl
0 VCL_call - timeout
0 VCL_return - discard
0 ExpKill - 0 0
0 ExpPick - 0 ttl
0 VCL_call - timeout
0 VCL_return - discard
0 ExpKill - 0 0
_______________________________________________
varnish-misc mailing list
[email protected]
http://projects.linpro.no/mailman/listinfo/varnish-misc
