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