[Varnish] #843: Sometime ESI are not interpreted
Varnish
varnish-bugs at varnish-cache.org
Wed Jan 12 10:25:10 CET 2011
#843: Sometime ESI are not interpreted
----------------------+-----------------------------------------------------
Reporter: nidosaur | Type: defect
Status: new | Priority: normal
Milestone: | Component: build
Version: 2.1.3 | Severity: normal
Keywords: |
----------------------+-----------------------------------------------------
Hi we have a problem on EZPublish site ESI enabled. Sometimes ESI are
interpreted and sometimes not. We are currently in varnish 2.1.3
{{{
varnishstat -1
client_conn 880512 15.06 Client connections accepted
client_drop 0 0.00 Connection dropped, no sess/wrk
client_req 4806872 82.20 Client requests received
cache_hit 7969831 136.29 Cache hits
cache_hitpass 0 0.00 Cache hits for pass
cache_miss 124448 2.13 Cache misses
backend_conn 162815 2.78 Backend conn. success
backend_unhealthy 0 0.00 Backend conn. not attempted
backend_busy 0 0.00 Backend conn. too many
backend_fail 219 0.00 Backend conn. failures
backend_reuse 72684 1.24 Backend conn. reuses
backend_toolate 51704 0.88 Backend conn. was closed
backend_recycle 124388 2.13 Backend conn. recycles
backend_unused 0 0.00 Backend conn. unused
fetch_head 0 0.00 Fetch head
fetch_length 73635 1.26 Fetch with Length
fetch_chunked 51665 0.88 Fetch chunked
fetch_eof 0 0.00 Fetch EOF
fetch_bad 0 0.00 Fetch had bad headers
fetch_close 69 0.00 Fetch wanted close
fetch_oldhttp 0 0.00 Fetch pre HTTP/1.1 closed
fetch_zero 49 0.00 Fetch zero len
fetch_failed 80 0.00 Fetch failed
n_sess_mem 674 . N struct sess_mem
n_sess 253 . N struct sess
n_object 19650 . N struct object
n_vampireobject 0 . N unresurrected objects
n_objectcore 19977 . N struct objectcore
n_objecthead 11795 . N struct objecthead
n_smf 45541 . N struct smf
n_smf_frag 1411 . N small free smf
n_smf_large 79 . N large free smf
n_vbe_conn 46 . N struct vbe_conn
n_wrk 400 . N worker threads
n_wrk_create 400 0.01 N worker threads created
n_wrk_failed 0 0.00 N worker threads not created
n_wrk_max 420377 7.19 N worker threads limited
n_wrk_queue 0 0.00 N queued work requests
n_wrk_overflow 163 0.00 N overflowed work requests
n_wrk_drop 0 0.00 N dropped work requests
n_backend 1 . N backends
n_expired 9690 . N expired objects
n_lru_nuked 94461 . N LRU nuked objects
n_lru_saved 0 . N LRU saved objects
n_lru_moved 3335607 . N LRU moved objects
n_deathrow 0 . N objects on deathrow
losthdr 0 0.00 HTTP header overflows
n_objsendfile 0 0.00 Objects sent with sendfile
n_objwrite 6028714 103.10 Objects sent with write
n_objoverflow 0 0.00 Objects overflowing workspace
s_sess 880450 15.06 Total Sessions
s_req 4806872 82.20 Total Requests
s_pipe 109695 1.88 Total pipe
s_pass 1524 0.03 Total pass
s_fetch 125338 2.14 Total fetch
s_hdrbytes 1831475536 31320.12 Total header bytes
s_bodybytes 58393321969 998586.12 Total body bytes
sess_closed 273287 4.67 Session Closed
sess_pipeline 5524 0.09 Session Pipeline
sess_readahead 5007 0.09 Session Read Ahead
sess_linger 4615604 78.93 Session Linger
sess_herd 4240874 72.52 Session herd
shm_records 240285980 4109.14 SHM records
shm_writes 15386982 263.13 SHM writes
shm_flushes 1116 0.02 SHM flushes due to overflow
shm_cont 1120 0.02 SHM MTX contention
shm_cycles 102 0.00 SHM cycles through buffer
sm_nreq 387119 6.62 allocator requests
sm_nobj 44051 . outstanding allocations
sm_balloc 934379520 . bytes allocated
sm_bfree 139362304 . bytes free
sma_nreq 0 0.00 SMA allocator requests
sma_nobj 0 . SMA outstanding allocations
sma_nbytes 0 . SMA outstanding bytes
sma_balloc 0 . SMA bytes allocated
sma_bfree 0 . SMA bytes free
sms_nreq 634 0.01 SMS allocator requests
sms_nobj 0 . SMS outstanding allocations
sms_nbytes 0 . SMS outstanding bytes
sms_balloc 265646 . SMS bytes allocated
sms_bfree 265646 . SMS bytes freed
backend_req 125805 2.15 Backend requests made
n_vcl 1 0.00 N vcl total
n_vcl_avail 1 0.00 N vcl available
n_vcl_discard 0 0.00 N vcl discarded
n_purge 1 . N total active purges
n_purge_add 1 0.00 N new purges added
n_purge_retire 0 0.00 N old purges deleted
n_purge_obj_test 0 0.00 N objects tested
n_purge_re_test 0 0.00 N regexps tested against
n_purge_dups 0 0.00 N duplicate purges removed
hcb_nolock 8094568 138.43 HCB Lookups without lock
hcb_lock 60306 1.03 HCB Lookups with lock
hcb_insert 60306 1.03 HCB Inserts
esi_parse 43401 0.74 Objects ESI parsed (unlock)
esi_errors 0 0.00 ESI parse errors (unlock)
accept_fail 0 0.00 Accept failures
client_drop_late 0 0.00 Connection dropped late
uptime 58476 1.00 Client uptime
}}}
{{{
default.vcl
backend www46 {
.host = "192.168.1.137";
.port = "80";
}
sub vcl_recv {
set req.backend = www46;
#Add a unique header containing the client address
unset req.http.X-Forwarded-For;
set req.http.X-Forwarded-For = client.ip;
# if (req.http.Cache-Control ~ "no-cache") {
# purge_url(req.url);
# }
##### always cache these items:
## images
if (req.request == "GET" && req.url ~
"\.(gif|jpg|jpeg|bmp|png|tiff|tif|ico|i
mg|tga|wmf)$") {
return (lookup);
}
## various other content pages
if (req.request == "GET" && req.url ~ "\.(css|js)$") {
return (lookup);
}
## multimedia
if (req.request == "GET" && req.url ~ "\.(svg|swf|mov|avi|wmv)$") {
return (lookup);
}
#### do not cache these rules:
# pass mode can't handle POST (yet)
if (req.request == "POST") {
return (pipe);
}
if (req.http.host != "www.site.fr"){
return (pipe);
}
if (req.request != "GET" && req.request != "HEAD") {
return (pipe);
}
if (req.http.Expect) {
return (pipe);
}
if (req.http.Authenticate || req.http.Authorization) {
return (pass);
}
if (req.http.Accept-Encoding) {
if (req.http.Accept-Encoding ~ "gzip") {
set req.http.Accept-Encoding = "gzip";
} elsif (req.http.Accept-Encoding ~ "deflate") {
set req.http.Accept-Encoding = "deflate";
} else {
# unkown algorithm
unset req.http.Accept-Encoding;
}
}
unset req.http.Accept-Encoding;
unset req.http.Vary;
#### don't cache authenticated sessions
if (req.http.Cookie && req.http.Cookie ~ "is_logged_in=" && req.url !~
"^/lay
out/set/esi") {
return(pass);
}
##// Varnish doesn't do INM requests so pass it through if no If-
Modified-Sin
ce was sent
if (req.http.If-None-Match && !req.http.If-Modified-Since) {
return (pass);
}
## don t cache these urls
if (req.url ~ "_pages/wpwidgets/wp-admin/") {
return (pipe);
}
#### if it passes all these tests, do a lookup anyway;
return (lookup);
}
sub vcl_pipe {
# # Note that only the first request to the backend will have
# # X-Forwarded-For set. If you use X-Forwarded-For and want to
# # have it set for all requests, make sure to have:
# # set bereq.http.connection = "close";
# # here. It is not set by default as it might break some broken web
# # applications, like IIS with NTLM authentication.
set bereq.http.PipeCache = "Pipeline";
return (pipe);
}
#
sub vcl_pass {
return (pass);
}
#
sub vcl_hash {
set req.hash += req.url;
if (req.http.host) {
set req.hash += req.http.host;
} else {
set req.hash += server.ip;
}
return (hash);
}
#
sub vcl_hit {
if (!obj.cacheable) {
return (pass);
}
return (deliver);
}
sub vcl_miss {
return (fetch);
}
#
sub vcl_fetch {
set beresp.ttl = 600s;
if( beresp.http.X-ttl ~ "s$"){ # seconds
C{
char *ttl;
ttl = VRT_GetHdr(sp, HDR_BERESP, "\06X-ttl:"); // 6 == 6
chars
VRT_l_beresp_ttl(sp, atoi(ttl));
}C
} elseif ( beresp.http.X-ttl ~ "m$") { # minutes
C{
char *ttl;
ttl = VRT_GetHdr(sp, HDR_BERESP, "\06X-ttl:"); // 6 == 6
chars
VRT_l_beresp_ttl(sp, atoi(ttl) * 60);
}C
} elseif ( beresp.http.X-ttl ~ "h$") { # hours
C{
char *ttl;
ttl = VRT_GetHdr(sp, HDR_BERESP, "\06X-ttl:"); // 6 == 6
chars
VRT_l_beresp_ttl(sp, atoi(ttl) * 60 * 60);
}C
}
esi;
# Varnish determined the object was not cacheable
if (!beresp.cacheable) {
set beresp.http.X-Cacheable = "NO:Not Cacheable";
# You don't wish to cache content for logged in users
} elsif(req.http.Cookie ~"(is_logged_in)") {
set beresp.http.X-Cacheable = "NO:Got Session";
# You are respecting the Cache-Control=private header from the
backend
} elsif ( beresp.http.Cache-Control ~ "private") {
set beresp.http.X-Cacheable = "NO:Cache-Control=private";
return(pass);
# Varnish determined the object was cacheable
} else {
set beresp.http.X-Cacheable = "YES";
}
if (!beresp.cacheable) {
return (pass);
}
if (beresp.http.Set-Cookie ~ "is_logged_in=deleted(.*)") {
return (deliver);
}
#if (beresp.http.Set-Cookie) {
# return (pass);
#}
if (req.request == "GET" && req.url ~
"\.(gif|jpg|jpeg|bmp|png|tiff|tif|ico
|img|tga|wmf)$") {
set beresp.ttl = 24h;
return (deliver);
}
## various other content pages
if (req.request == "GET" && req.url ~ "\.(css|js)$") {
set beresp.ttl = 24h;
return (deliver);
}
## multimedia
if (req.request == "GET" && req.url ~
"\.(svg|swf|ico|mp3|mp4|m4a|ogg|mov|a
vi|wmv)$") {
set beresp.ttl = 24h;
return (deliver);
}
# grace
if ( beresp.status == 500) {
set beresp.grace = 1h;
restart;
}
set beresp.grace = 1h;
return (deliver);
}
#
sub vcl_deliver {
if (obj.hits > 0) {
set resp.http.X-Cache = "HIT";
set resp.http.X-Cache-Hits = obj.hits;
} else {
set resp.http.X-Cache = "MISS";
}
set resp.http.WhoisCache = "TopProxy";
return (deliver);
}
#
}}}
when esi is not interpreted, we can see in code source the esi load
{{{
<div class="bloctwo">
<esi:include
src="/layout/set/esi/content/view/line/211545/(ss_view)/bloctwo" />
</div>
<div
class="bloctwo">
<esi:include src="/layout/set/esi/content/view/line/356/(ss_view)/bloctwo"
/>
</div>
}}}
I have tried to modify differents parameters but there's always the same
result : sometime all ESI are interpreted and sometimes none.
{{{
param.show
200 2375
acceptor_sleep_decay 0.900000 []
acceptor_sleep_incr 0.001000 [s]
acceptor_sleep_max 0.050000 [s]
auto_restart on [bool]
ban_lurker_sleep 0.000000 [s]
between_bytes_timeout 300.000000 [s]
cache_vbe_conns off [bool]
cc_command "exec cc -fpic -shared -Wl,-x -o %o %s"
cli_buffer 8192 [bytes]
cli_timeout 10 [seconds]
clock_skew 10 [s]
connect_timeout 300.000000 [s]
critbit_cooloff 180.000000 [s]
default_grace 10 [seconds]
default_ttl 600 [seconds]
diag_bitmap 0x0 [bitmap]
err_ttl 0 [seconds]
esi_syntax 1 [bitmap]
fetch_chunksize 128 [kilobytes]
first_byte_timeout 300.000000 [s]
group nogroup (65534)
http_headers 64 [header lines]
http_range_support off [bool]
listen_address :80
listen_depth 1024 [connections]
log_hashstring off [bool]
log_local_address off [bool]
lru_interval 2 [seconds]
max_esi_includes 10 [includes]
max_restarts 4 [restarts]
overflow_max 100 [%]
ping_interval 3 [seconds]
pipe_timeout 60 [seconds]
prefer_ipv6 off [bool]
purge_dups on [bool]
rush_exponent 3 [requests per request]
saintmode_threshold 10 [objects]
send_timeout 600 [seconds]
sess_timeout 5 [seconds]
sess_workspace 32768 [bytes]
session_linger 50 [ms]
session_max 100000 [sessions]
shm_reclen 255 [bytes]
shm_workspace 8192 [bytes]
syslog_cli_traffic on [bool]
thread_pool_add_delay 20 [milliseconds]
thread_pool_add_threshold 2 [requests]
thread_pool_fail_delay 200 [milliseconds]
thread_pool_max 2000 [threads]
thread_pool_min 200 [threads]
thread_pool_purge_delay 1000 [milliseconds]
thread_pool_stack unlimited [bytes]
thread_pool_timeout 100 [seconds]
thread_pools 2 [pools]
thread_stats_rate 10 [requests]
user nobody (65534)
vcl_trace off [bool]
waiter default (epoll, poll)
}}}
I don't know if it's the same cas of http://www.varnish-
cache.org/trac/ticket/805
but I've got also negative ReqEnd
{{{
Varnish:~# varnishlog | grep nan
83 ReqEnd - 1460013818 1294824278.541809559 1294824281.333508492
-2.791691780 nan nan
97 ReqEnd - 1460013630 1294824277.736756325 1294824281.742346287
-3.734101057 nan nan
334 ReqEnd - 1460014066 1294824279.950573683 1294824282.971493483
-2.936873913 nan nan
101 ReqEnd c 1460014725 1294824283.651019812 1294824283.726319790
-0.075284481 nan nan
82 ReqEnd c 1460014601 1294824282.742613554 1294824283.744442940
-1.001822472 nan nan
214 ReqEnd c 1460014687 1294824283.311659813 1294824285.048683643
-1.737019062 nan nan
32 ReqEnd c 1460014895 1294824284.836895704 1294824285.345507860
-0.381927729 nan nan
298 ReqEnd - 1460014196 1294824280.686220884 1294824285.820836782
-4.761623859 nan nan
117 ReqEnd c 1460014540 1294824282.388427496 1294824286.035535336
-3.647100687 nan nan
245 ReqEnd - 1460014122 1294824280.186545134 1294824286.089832306
-5.662771463 nan nan
117 ReqEnd c 1460015132 1294824286.105287313 1294824286.161284924
-0.055979967 nan nan
331 ReqEnd c 1460015096 1294824285.907188416 1294824286.372141600
-0.464935541 nan nan
122 ReqEnd - 1460013821 1294824278.552110434 1294824286.479575396
-3.372597456 nan nan
240 ReqEnd c 1460014974 1294824285.243790865 1294824286.903476715
-1.659677982 nan nan
164 ReqEnd - 1460014148 1294824280.382161617 1294824287.273322344
-6.556917667 nan nan
20 ReqEnd c 1460014891 1294824284.788542747 1294824287.581802368
-1.827905655 nan nan
79 ReqEnd c 1460015391 1294824287.458260298 1294824288.009994507
-0.551726580 nan nan
}}}
--
Ticket URL: <http://www.varnish-cache.org/trac/ticket/843>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list