<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=utf-8">
</head>
<body text="#000000" bgcolor="#FFFFFF">
<br>
<div class="moz-forward-container">
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
I'm running Varnish 4.1.1 on CentOS6. When I retrieve a resource
through<br>
Varnish using curl, I get a 'transfer closed with 29700 bytes
remaining<br>
to read'. I'm running with the default.vcl that came with the
rpm, except<br>
that I changed the backend default.host to point to my origin
server.<br>
<br>
Details of the transaction are below. The most suspicious, to me,<br>
are the 'Fetch error - Could not get storage' and the long series
of<br>
ExpKill that precedes it. But even if no space is<br>
available for caching, Varnish shouldn't return truncated content
to the <br>
client, should it?<br>
<br>
Is this a Varnish bug? Any advice on how to diagnose this further
would be greatly<br>
appreciated. <br>
<br>
Thanks,<br>
John Salmon<br>
<br>
Here is the output from curl -vvv. <br>
<br>
drdws0047$ curl -H X-Fs123-Protocol:3 -H
X-Fs123-Cache-Flush-Trigger:1 -H X-Fs123-Chunk:8388608@0 -vvv <a
moz-do-not-send="true" class="moz-txt-link-freetext"
href="http://127.0.0.1:82/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00"><a class="moz-txt-link-freetext" href="http://127.0.0.1:82/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00">http://127.0.0.1:82/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00</a></a>|
wc<br>
* About to connect() to 127.0.0.1 port 82 (#0)<br>
* Trying 127.0.0.1... connected<br>
* Connected to 127.0.0.1 (127.0.0.1) port 82 (#0)<br>
> GET
/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00
HTTP/1.1<br>
> User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu)
libcurl/7.19.7 NSS/3.19.1 Basic ECC zlib/1.2.3 libidn/1.18
libssh2/1.4.2<br>
> Host: 127.0.0.1:82<br>
> Accept: */*<br>
> X-Fs123-Protocol:3<br>
> X-Fs123-Cache-Flush-Trigger:1<br>
> X-Fs123-Chunk:8388608@0<br>
> <br>
% Total % Received % Xferd Average Speed Time Time
Time Current<br>
Dload Upload Total Spent
Left Speed<br>
0 0 0 0 0 0 0 0 --:--:-- --:--:--
--:--:-- 0< HTTP/1.1 200 OK<br>
< Date: Tue, 05 Apr 2016 13:49:55 GMT<br>
< Server: Apache/2.2.15 (CentOS)<br>
< Vary:
X-Fs123-Cache-Flush-Trigger,X-Fs123-Protocol,X-Fs123-Chunk<br>
< X-Fs123-Protocol: 3<br>
< X-Fs123-Cache-Flush-Trigger: 1<br>
< Cache-Control: public,max-age=1000000<br>
< Last-Modified: Thu, 09 Jan 2014 18:33:57 GMT<br>
< X-Fs123-Attrs: 0 33133 1 10085 10 1126399 1389292437
1429799855 1459863979 27355334 0 221649590 888201093 32<br>
< X-Fs123-Content-Chunk: 1126399@0<br>
< Content-Length: 1126399<br>
< Content-Type: application/octet-stream<br>
< X-Varnish: 75556<br>
< Age: 0<br>
< Via: 1.1 varnish-v4<br>
< Accept-Ranges: bytes<br>
< Connection: keep-alive<br>
< <br>
{ [data not shown]<br>
* transfer closed with 29700 bytes remaining to read<br>
97 1099k 97 1070k 0 0 7150k 0 --:--:-- --:--:--
--:--:-- 7285k* Closing connection #0<br>
<br>
curl: (18) transfer closed with 29700 bytes remaining to read<br>
3568 17393 1096699<br>
drdws0047$ <br>
<br>
Here are the relevant transactions from varnishlog:<br>
<br>
<br>
* << BeReq >> 75557 <br>
- Begin bereq 75556 fetch<br>
- Timestamp Start: 1459864195.876974 0.000000 0.000000<br>
- BereqMethod GET<br>
- BereqURL
/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00<br>
- BereqProtocol HTTP/1.1<br>
- BereqHeader User-Agent: curl/7.19.7
(x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.19.1 Basic ECC
zlib/1.2.3 libidn/1.18 libssh2/1.4.2<br>
- BereqHeader Host: 127.0.0.1:82<br>
- BereqHeader Accept: */*<br>
- BereqHeader X-Fs123-Protocol:3<br>
- BereqHeader X-Fs123-Cache-Flush-Trigger:1<br>
- BereqHeader X-Fs123-Chunk:8388608@0<br>
- BereqHeader X-Forwarded-For: 127.0.0.1<br>
- BereqHeader Accept-Encoding: gzip<br>
- BereqHeader X-Varnish: 75557<br>
- VCL_call BACKEND_FETCH<br>
- VCL_return fetch<br>
- BackendOpen 15 reload_2016-04-04T18:49:45.default
149.77.52.249 80 149.77.52.153 39650<br>
- Timestamp Bereq: 1459864195.877410 0.000435 0.000435<br>
- Timestamp Beresp: 1459864195.995047 0.118073 0.117638<br>
- BerespProtocol HTTP/1.1<br>
- BerespStatus 200<br>
- BerespReason OK<br>
- BerespHeader Date: Tue, 05 Apr 2016 13:49:55 GMT<br>
- BerespHeader Server: Apache/2.2.15 (CentOS)<br>
- BerespHeader Vary:
X-Fs123-Cache-Flush-Trigger,X-Fs123-Protocol,X-Fs123-Chunk<br>
- BerespHeader X-Fs123-Protocol: 3<br>
- BerespHeader X-Fs123-Cache-Flush-Trigger: 1<br>
- BerespHeader Cache-Control: public,max-age=1000000<br>
- BerespHeader Last-Modified: Thu, 09 Jan 2014 18:33:57 GMT<br>
- BerespHeader X-Fs123-Attrs: 0 33133 1 10085 10 1126399
1389292437 1429799855 1459863979 27355334 0 221649590 888201093 32<br>
- BerespHeader X-Fs123-Content-Chunk: 1126399@0<br>
- BerespHeader Content-Length: 1126399<br>
- BerespHeader Connection: close<br>
- BerespHeader Content-Type: application/octet-stream<br>
- TTL RFC 1000000 10 -1 1459864196 1459864196
1459864195 0 1000000<br>
- VCL_call BACKEND_RESPONSE<br>
- VCL_return deliver<br>
- Storage malloc s0<br>
- ObjProtocol HTTP/1.1<br>
- ObjStatus 200<br>
- ObjReason OK<br>
- ObjHeader Date: Tue, 05 Apr 2016 13:49:55 GMT<br>
- ObjHeader Server: Apache/2.2.15 (CentOS)<br>
- ObjHeader Vary:
X-Fs123-Cache-Flush-Trigger,X-Fs123-Protocol,X-Fs123-Chunk<br>
- ObjHeader X-Fs123-Protocol: 3<br>
- ObjHeader X-Fs123-Cache-Flush-Trigger: 1<br>
- ObjHeader Cache-Control: public,max-age=1000000<br>
- ObjHeader Last-Modified: Thu, 09 Jan 2014 18:33:57 GMT<br>
- ObjHeader X-Fs123-Attrs: 0 33133 1 10085 10 1126399
1389292437 1429799855 1459863979 27355334 0 221649590 888201093 32<br>
- ObjHeader X-Fs123-Content-Chunk: 1126399@0<br>
- ObjHeader Content-Length: 1126399<br>
- ObjHeader Content-Type: application/octet-stream<br>
- Fetch_Body 3 length stream<br>
- ExpKill LRU_Cand p=0x2b121483cf40 f=0x0 r=1<br>
- ExpKill LRU x=66088<br>
- ExpKill LRU_Cand p=0x2b12148400c0 f=0x0 r=1<br>
- ExpKill LRU x=66090<br>
- ExpKill LRU_Cand p=0x2b1214840180 f=0x0 r=1<br>
- ExpKill LRU x=66092<br>
- ExpKill LRU_Cand p=0x2b1214840240 f=0x0 r=1<br>
- ExpKill LRU x=66094<br>
- ExpKill LRU_Cand p=0x2b1214840300 f=0x0 r=1<br>
- ExpKill LRU x=66096<br>
- ExpKill LRU_Cand p=0x2b12148403c0 f=0x0 r=1<br>
- ExpKill LRU x=66098<br>
- ExpKill LRU_Cand p=0x2b1214840480 f=0x0 r=1<br>
- ExpKill LRU x=66100<br>
- ExpKill LRU_Cand p=0x2b1214840540 f=0x0 r=1<br>
- ExpKill LRU x=66102<br>
- ExpKill LRU_Cand p=0x2b1214840780 f=0x0 r=1<br>
- ExpKill LRU x=66110<br>
- ExpKill LRU_Cand p=0x2b1214840840 f=0x0 r=1<br>
- ExpKill LRU x=66115<br>
- ExpKill LRU_Cand p=0x2b1214840900 f=0x0 r=1<br>
- ExpKill LRU x=66117<br>
- ExpKill LRU_Cand p=0x2b12148409c0 f=0x0 r=1<br>
- ExpKill LRU x=66119<br>
- ExpKill LRU_Cand p=0x2b1214840a80 f=0x0 r=1<br>
- ExpKill LRU x=66121<br>
- ExpKill LRU_Cand p=0x2b1214840b40 f=0x0 r=1<br>
- ExpKill LRU x=66123<br>
- ExpKill LRU_Cand p=0x2b1214840c00 f=0x0 r=1<br>
- ExpKill LRU x=66125<br>
- ExpKill LRU_Cand p=0x2b1214840cc0 f=0x0 r=1<br>
- ExpKill LRU x=66127<br>
- ExpKill LRU_Cand p=0x2b1214840d80 f=0x0 r=1<br>
- ExpKill LRU x=66129<br>
- ExpKill LRU_Cand p=0x2b1214840e40 f=0x0 r=1<br>
- ExpKill LRU x=66131<br>
- ExpKill LRU_Cand p=0x2b1214840f00 f=0x0 r=1<br>
- ExpKill LRU x=66133<br>
- ExpKill LRU_Cand p=0x2b1214840fc0 f=0x0 r=1<br>
- ExpKill LRU x=66135<br>
- ExpKill LRU_Cand p=0x2b1214841080 f=0x0 r=1<br>
- ExpKill LRU x=66137<br>
- ExpKill LRU_Cand p=0x2b1214841140 f=0x0 r=1<br>
- ExpKill LRU x=66139<br>
- ExpKill LRU_Cand p=0x2b1214841200 f=0x0 r=1<br>
- ExpKill LRU x=66141<br>
- ExpKill LRU_Cand p=0x2b12148412c0 f=0x0 r=1<br>
- ExpKill LRU x=66143<br>
- ExpKill LRU_Cand p=0x2b1214841380 f=0x0 r=1<br>
- ExpKill LRU x=66145<br>
- ExpKill LRU_Cand p=0x2b1214841440 f=0x0 r=1<br>
- ExpKill LRU x=66147<br>
- ExpKill LRU_Cand p=0x2b1214841500 f=0x0 r=1<br>
- ExpKill LRU x=66149<br>
- ExpKill LRU_Cand p=0x2b12148415c0 f=0x0 r=1<br>
- ExpKill LRU x=66151<br>
- ExpKill LRU_Cand p=0x2b1214841680 f=0x0 r=1<br>
- ExpKill LRU x=66153<br>
- ExpKill LRU_Cand p=0x2b1214841740 f=0x0 r=1<br>
- ExpKill LRU x=66155<br>
- ExpKill LRU_Cand p=0x2b1214841800 f=0x0 r=1<br>
- ExpKill LRU x=66157<br>
- ExpKill LRU_Cand p=0x2b12148418c0 f=0x0 r=1<br>
- ExpKill LRU x=66159<br>
- ExpKill LRU_Cand p=0x2b1214841980 f=0x0 r=1<br>
- ExpKill LRU x=66161<br>
- ExpKill LRU_Cand p=0x2b1214841a40 f=0x0 r=1<br>
- ExpKill LRU x=66163<br>
- ExpKill LRU_Cand p=0x2b1214841b00 f=0x0 r=1<br>
- ExpKill LRU x=66165<br>
- ExpKill LRU_Cand p=0x2b1214841bc0 f=0x0 r=1<br>
- ExpKill LRU x=66167<br>
- ExpKill LRU_Cand p=0x2b1214841c80 f=0x0 r=1<br>
- ExpKill LRU x=66169<br>
- ExpKill LRU_Cand p=0x2b1214841d40 f=0x0 r=1<br>
- ExpKill LRU x=66171<br>
- ExpKill LRU_Cand p=0x2b1214841e00 f=0x0 r=1<br>
- ExpKill LRU x=66173<br>
- ExpKill LRU_Cand p=0x2b1214841ec0 f=0x0 r=1<br>
- ExpKill LRU x=66175<br>
- ExpKill LRU_Cand p=0x2b1214841f80 f=0x0 r=1<br>
- ExpKill LRU x=66177<br>
- ExpKill LRU_Cand p=0x2b1214842040 f=0x0 r=1<br>
- ExpKill LRU x=66179<br>
- ExpKill LRU_Cand p=0x2b1214842100 f=0x0 r=1<br>
- ExpKill LRU x=66181<br>
- ExpKill LRU_Cand p=0x2b12148421c0 f=0x0 r=1<br>
- ExpKill LRU x=66183<br>
- ExpKill LRU_Cand p=0x2b1214842280 f=0x0 r=1<br>
- ExpKill LRU x=66185<br>
- ExpKill LRU_Cand p=0x2b1214842340 f=0x0 r=1<br>
- ExpKill LRU x=66187<br>
- ExpKill LRU_Cand p=0x2b1214842400 f=0x0 r=1<br>
- ExpKill LRU x=66189<br>
- ExpKill LRU_Cand p=0x2b12148424c0 f=0x0 r=1<br>
- ExpKill LRU x=66191<br>
- ExpKill LRU_Cand p=0x2b1214842580 f=0x0 r=1<br>
- ExpKill LRU x=66193<br>
- ExpKill LRU_Cand p=0x2b1214842640 f=0x0 r=1<br>
- ExpKill LRU x=66195<br>
- ExpKill LRU_Cand p=0x2b1214842700 f=0x0 r=1<br>
- ExpKill LRU x=66197<br>
- ExpKill LRU_Cand p=0x2b12148427c0 f=0x0 r=1<br>
- ExpKill LRU x=66199<br>
- ExpKill LRU_Cand p=0x2b1214842880 f=0x0 r=1<br>
- ExpKill LRU x=66201<br>
- ExpKill LRU_Cand p=0x2b1214842940 f=0x0 r=1<br>
- ExpKill LRU x=66203<br>
- ExpKill LRU_Cand p=0x2b1214842a00 f=0x0 r=1<br>
- ExpKill LRU x=66205<br>
- ExpKill LRU_Cand p=0x2b1214842ac0 f=0x0 r=1<br>
- ExpKill LRU x=66207<br>
- ExpKill LRU_Cand p=0x2b1214842b80 f=0x0 r=1<br>
- ExpKill LRU x=66209<br>
- ExpKill LRU_Cand p=0x2b1214842c40 f=0x0 r=1<br>
- ExpKill LRU x=66211<br>
- ExpKill LRU_Cand p=0x2b1214842d00 f=0x0 r=1<br>
- ExpKill LRU x=66213<br>
- ExpKill LRU_Cand p=0x2b1214842dc0 f=0x0 r=1<br>
- ExpKill LRU x=66215<br>
- ExpKill LRU_Cand p=0x2b1214842e80 f=0x0 r=1<br>
- ExpKill LRU x=66217<br>
- ExpKill LRU_Cand p=0x2b1214842f40 f=0x0 r=1<br>
- ExpKill LRU x=66219<br>
- ExpKill LRU_Cand p=0x2b12148470c0 f=0x0 r=1<br>
- ExpKill LRU x=66221<br>
- ExpKill LRU_Cand p=0x2b1214847180 f=0x0 r=1<br>
- ExpKill LRU x=66223<br>
- ExpKill LRU_Cand p=0x2b1214847240 f=0x0 r=1<br>
- ExpKill LRU x=66225<br>
- ExpKill LRU_Cand p=0x2b1214847300 f=0x0 r=1<br>
- ExpKill LRU x=66227<br>
- ExpKill LRU_Cand p=0x2b12148473c0 f=0x0 r=1<br>
- ExpKill LRU x=66229<br>
- ExpKill LRU_Cand p=0x2b1214847480 f=0x0 r=1<br>
- ExpKill LRU x=66231<br>
- ExpKill LRU_Cand p=0x2b1214847540 f=0x0 r=1<br>
- ExpKill LRU x=66233<br>
- ExpKill LRU_Cand p=0x2b1214847600 f=0x0 r=1<br>
- ExpKill LRU x=66235<br>
- ExpKill LRU_Cand p=0x2b12148476c0 f=0x0 r=1<br>
- ExpKill LRU x=66237<br>
- ExpKill LRU_Cand p=0x2b1214847780 f=0x0 r=1<br>
- ExpKill LRU x=66239<br>
- ExpKill LRU_Cand p=0x2b1214847840 f=0x0 r=1<br>
- ExpKill LRU x=66241<br>
- ExpKill LRU_Cand p=0x2b1214847900 f=0x0 r=1<br>
- ExpKill LRU x=66243<br>
- ExpKill LRU_Cand p=0x2b12148479c0 f=0x0 r=1<br>
- ExpKill LRU x=66245<br>
- ExpKill LRU_Cand p=0x2b1214847a80 f=0x0 r=1<br>
- ExpKill LRU x=66247<br>
- FetchError Could not get storage<br>
- BackendClose 15 reload_2016-04-04T18:49:45.default<br>
- BereqAcct 382 0 382 521 1096699 1097220<br>
- End <br>
<br>
* << Request >> 75556 <br>
- Begin req 75555 rxreq<br>
- Timestamp Start: 1459864195.876911 0.000000 0.000000<br>
- Timestamp Req: 1459864195.876911 0.000000 0.000000<br>
- ReqStart 127.0.0.1 48471<br>
- ReqMethod GET<br>
- ReqURL
/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00<br>
- ReqProtocol HTTP/1.1<br>
- ReqHeader User-Agent: curl/7.19.7
(x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.19.1 Basic ECC
zlib/1.2.3 libidn/1.18 libssh2/1.4.2<br>
- ReqHeader Host: 127.0.0.1:82<br>
- ReqHeader Accept: */*<br>
- ReqHeader X-Fs123-Protocol:3<br>
- ReqHeader X-Fs123-Cache-Flush-Trigger:1<br>
- ReqHeader X-Fs123-Chunk:8388608@0<br>
- ReqHeader X-Forwarded-For: 127.0.0.1<br>
- VCL_call RECV<br>
- VCL_return hash<br>
- VCL_call HASH<br>
- VCL_return lookup<br>
- VCL_call MISS<br>
- VCL_return fetch<br>
- Link bereq 75557 fetch<br>
- Timestamp Fetch: 1459864195.995156 0.118245 0.118245<br>
- RespProtocol HTTP/1.1<br>
- RespStatus 200<br>
- RespReason OK<br>
- RespHeader Date: Tue, 05 Apr 2016 13:49:55 GMT<br>
- RespHeader Server: Apache/2.2.15 (CentOS)<br>
- RespHeader Vary:
X-Fs123-Cache-Flush-Trigger,X-Fs123-Protocol,X-Fs123-Chunk<br>
- RespHeader X-Fs123-Protocol: 3<br>
- RespHeader X-Fs123-Cache-Flush-Trigger: 1<br>
- RespHeader Cache-Control: public,max-age=1000000<br>
- RespHeader Last-Modified: Thu, 09 Jan 2014 18:33:57 GMT<br>
- RespHeader X-Fs123-Attrs: 0 33133 1 10085 10 1126399
1389292437 1429799855 1459863979 27355334 0 221649590 888201093 32<br>
- RespHeader X-Fs123-Content-Chunk: 1126399@0<br>
- RespHeader Content-Length: 1126399<br>
- RespHeader Content-Type: application/octet-stream<br>
- RespHeader X-Varnish: 75556<br>
- RespHeader Age: 0<br>
- RespHeader Via: 1.1 varnish-v4<br>
- VCL_call DELIVER<br>
- VCL_return deliver<br>
- Timestamp Process: 1459864195.995174 0.118263 0.000018<br>
- RespHeader Accept-Ranges: bytes<br>
- Debug "RES_MODE 2"<br>
- RespHeader Connection: keep-alive<br>
- Timestamp Resp: 1459864196.005802 0.128891 0.010628<br>
- ReqAcct 313 0 313 595 1096699 1097294<br>
- End <br>
<br>
* << Session >> 75555 <br>
- Begin sess 0 HTTP/1<br>
- SessOpen 127.0.0.1 48471 127.0.0.1:82 127.0.0.1 82
1459864195.876869 12<br>
- Link req 75556 rxreq<br>
- SessClose REM_CLOSE 0.129<br>
- End <br>
<br>
<br>
And here is the corresponding entry from the origin servers
access_log:<br>
<br>
[root@nycovirttest8 conf.d]# grep inchi /var/log/httpd/access_log<br>
149.77.52.153 - - [05/Apr/2016:09:49:55 -0400] "GET
/fs123/m5/03-fs123.3.fcgi/inchi/1.04-05/lib/libinchi.so.1.04.00
HTTP/1.1" 200 1126399 "8388608@0" "-" "curl/7.19.7
(x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.19.1 Basic ECC
zlib/1.2.3 libidn/1.18 libssh2/1.4.2"<br>
[root@nycovirttest8 conf.d]# <br>
<br>
<br>
The varnish I'm using is:<br>
<br>
drdws0047$ rpm -qi varnish<br>
Name : varnish Relocations: (not
relocatable)<br>
Version : 4.1.1 Vendor: (none)<br>
Release : 2.el6 Build Date: Mon 01 Feb
2016 11:56:49 AM EST<br>
Install Date: Wed 10 Feb 2016 05:25:48 PM EST Build Host:
nancy.varnish-software.com<br>
Group : System Environment/Daemons Source RPM:
varnish-4.1.1-2.el6.src.rpm<br>
Size : 1066319 License: BSD<br>
Signature : RSA/SHA1, Mon 01 Feb 2016 12:07:15 PM EST, Key ID
60e7c096c4deffeb<br>
URL : <a moz-do-not-send="true"
class="moz-txt-link-freetext"
href="https://www.varnish-cache.org/">https://www.varnish-cache.org/</a><br>
Summary : High-performance HTTP accelerator<br>
<br>
<br>
<br>
<div class="moz-signature">-- <br>
<b>.</b></div>
<br>
</div>
<br>
</body>
</html>