Duplicated Content-Length headers on pass
Mikhail Mazursky
ash2kk at gmail.com
Thu Oct 28 07:31:12 CEST 2010
2010/10/27 Tollef Fog Heen <tfheen at varnish-software.com>:
> ]] Mikhail Mazursky
>
> Hi,
>
> | 2010/10/26 Tollef Fog Heen <tfheen at varnish-software.com>:
> | >
> | > Hi all,
> | >
> | > it seems like a small, but pesky bug snuck its way into 2.1.4, in which
> | > you might see duplicated Content-Length headers when using pass.
> | >
> | > As a workaround for this, I believe doing
> | >
> | > sub vcl_fetch {
> | > if (req.request != "HEAD") {
> | > unset beresp.http.content-length;
> | > }
> | > }
> | That workaround don't work for me. Piece of my VCL:
>
> Can you please provide varnishlog showing that we're sending out a
> duplicated Content-Length header?
Hi,
It seems that the workaround actually works BUT something goes wrong
in another way. Some timeouts happen and Content-Length is zero. I
attached files with tests i made.
Attached image shows one minute timeout, which happens on server which
balances requests between varnishes on two servers. I use nginx to
balance requests using cache array routing protocol.
nginx is configured to failover after 60 seconds to another varnish backed.
I also attached the VCL file i tested with.
And that's what i see in nginx's error log when timeouts happen (the
port is 1380 when i run varnish in production and i change it to 1381
to remove actual traffic from it; this is a part of production log):
# cat /var/log/nginx-error/**********.error.log | grep
92ed2d89c293116b5e06d966f7f238e0.jpg
2010/10/28 09:57:21 [error] 55417#0: *227171859 upstream timed out
(60: Operation timed out) while reading response header from upstream,
client: **********, server: **********, request: "GET
/box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg HTTP/1.1", upstream:
"http://127.0.0.1:1380/box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg",
host: "**********"
Hope this helps and thanks for this great piece of software!
-------------- next part --------------
with patched VCL:
# telnet 127.0.0.1 1381
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg HTTP/1.1
Host: *********
HTTP/1.1 200 OK
Server: nginx
Content-Type: image/jpeg
Last-Modified: Mon, 06 Sep 2010 09:55:59 GMT
Expires: Thu, 31 Dec 2037 23:55:55 GMT
Cache-Control: max-age=315360000
Content-Length: 0
Date: Thu, 28 Oct 2010 04:55:25 GMT
X-Varnish: 868874587
Age: 0
Via: 1.1 varnish
Connection: keep-alive
Connection closed by foreign host.
varnishlog output:
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288241806 1.0
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288241809 1.0
6 SessionOpen c 127.0.0.1 49451 127.0.0.1:1381
6 Debug c "herding"
6 ReqStart c 127.0.0.1 49451 868874588
6 RxRequest c GET
6 RxURL c /box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg
6 RxProtocol c HTTP/1.1
6 RxHeader c Host: *********
6 VCL_call c recv
6 VCL_return c lookup
6 VCL_call c hash
6 VCL_return c hash
6 Hit c 868874587
6 VCL_call c hit
6 VCL_return c deliver
6 VCL_call c deliver
6 VCL_return c deliver
6 TxProtocol c HTTP/1.1
6 TxStatus c 200
6 TxResponse c OK
6 TxHeader c Server: nginx
6 TxHeader c Content-Type: image/jpeg
6 TxHeader c Last-Modified: Mon, 06 Sep 2010 09:55:59 GMT
6 TxHeader c Expires: Thu, 31 Dec 2037 23:55:55 GMT
6 TxHeader c Cache-Control: max-age=315360000
6 TxHeader c Content-Length: 0
6 TxHeader c Date: Thu, 28 Oct 2010 04:56:50 GMT
6 TxHeader c X-Varnish: 868874588 868874587
6 TxHeader c Age: 86
6 TxHeader c Via: 1.1 varnish
6 TxHeader c Connection: keep-alive
6 Length c 0
6 ReqEnd c 868874588 1288241810.851414680 1288241810.851518393 0.638790131 0.000051975 0.000051737
6 Debug c "herding"
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288241812 1.0
6 SessionClose c timeout
6 StatSess c 127.0.0.1 49451 1 1 1 0 0 0 319 0
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288241815 1.0
-------------- next part --------------
with patched VCL and no-cache:
# telnet 127.0.0.1 1381
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg HTTP/1.1
Host: *********
Cache-Control: no-cache
HTTP/1.1 200 OK
Server: nginx
Content-Type: image/jpeg
Last-Modified: Mon, 06 Sep 2010 09:55:59 GMT
Expires: Thu, 31 Dec 2037 23:55:55 GMT
Cache-Control: max-age=315360000
Content-Length: 0
Date: Thu, 28 Oct 2010 05:01:29 GMT
X-Varnish: 868874589
Age: 0
Via: 1.1 varnish
Connection: keep-alive
Connection closed by foreign host.
varnishlog output:
6 SessionOpen c 127.0.0.1 55271 127.0.0.1:1381
6 Debug c "herding"
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288242087 1.0
6 ReqStart c 127.0.0.1 55271 868874589
6 RxRequest c GET
6 RxURL c /box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg
6 RxProtocol c HTTP/1.1
6 RxHeader c Host: *********
6 RxHeader c Cache-Control: no-cache
6 VCL_call c recv
6 VCL_return c lookup
6 VCL_call c hash
6 VCL_return c hash
6 ExpBan c 868874587 was banned
6 VCL_call c miss
6 VCL_return c fetch
10 BackendClose - default
10 BackendOpen b default 127.0.0.1 55347 127.0.0.1 380
6 Backend c 10 default default
10 TxRequest b GET
10 TxURL b /box/132x99/92ed2d89c293116b5e06d966f7f238e0.jpg
10 TxProtocol b HTTP/1.1
10 TxHeader b Host: *********
10 TxHeader b X-Forwarded-For: 127.0.0.1
10 TxHeader b X-Varnish: 868874589
10 RxProtocol b HTTP/1.1
10 RxStatus b 200
10 RxResponse b OK
10 RxHeader b Server: nginx
10 RxHeader b Date: Thu, 28 Oct 2010 05:01:29 GMT
10 RxHeader b Content-Type: image/jpeg
10 RxHeader b Connection: keep-alive
10 RxHeader b Content-Length: 3067
10 RxHeader b Last-Modified: Mon, 06 Sep 2010 09:55:59 GMT
10 RxHeader b Expires: Thu, 31 Dec 2037 23:55:55 GMT
10 RxHeader b Cache-Control: max-age=315360000
10 RxHeader b Accept-Ranges: bytes
6 TTL c 868874589 RFC 315360000 1288242089 0 0 315360000 0
6 VCL_call c fetch
6 VCL_return c deliver
6 ObjProtocol c HTTP/1.1
6 ObjStatus c 200
6 ObjResponse c OK
6 ObjHeader c Server: nginx
6 ObjHeader c Date: Thu, 28 Oct 2010 05:01:29 GMT
6 ObjHeader c Content-Type: image/jpeg
6 ObjHeader c Last-Modified: Mon, 06 Sep 2010 09:55:59 GMT
6 ObjHeader c Expires: Thu, 31 Dec 2037 23:55:55 GMT
6 ObjHeader c Cache-Control: max-age=315360000
10 Length b 0
10 BackendReuse b default
6 VCL_call c deliver
6 VCL_return c deliver
6 TxProtocol c HTTP/1.1
6 TxStatus c 200
6 TxResponse c OK
6 TxHeader c Server: nginx
6 TxHeader c Content-Type: image/jpeg
6 TxHeader c Last-Modified: Mon, 06 Sep 2010 09:55:59 GMT
6 TxHeader c Expires: Thu, 31 Dec 2037 23:55:55 GMT
6 TxHeader c Cache-Control: max-age=315360000
6 TxHeader c Content-Length: 0
6 TxHeader c Date: Thu, 28 Oct 2010 05:01:29 GMT
6 TxHeader c X-Varnish: 868874589
6 TxHeader c Age: 0
6 TxHeader c Via: 1.1 varnish
6 TxHeader c Connection: keep-alive
6 Length c 0
6 ReqEnd c 868874589 1288242089.776962996 1288242089.782082319 2.879873037 0.005076170 0.000043154
6 Debug c "herding"
0 ExpKill - 868874587 -1288242090
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288242090 1.0
0 CLI - Rd ping
0 CLI - Wr 200 19 PONG 1288242093 1.0
6 SessionClose c timeout
6 StatSess c 127.0.0.1 55271 3 1 1 0 0 1 308 0
-------------- next part --------------
A non-text attachment was scrubbed...
Name: timeouts.png
Type: image/png
Size: 129101 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20101028/a01bfe58/attachment-0003.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: custom.vcl
Type: application/octet-stream
Size: 2533 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20101028/a01bfe58/attachment-0003.obj>
More information about the varnish-misc
mailing list