[Varnish] #965: Restarting a request in vcl_miss causes Varnish client crash.
Varnish
varnish-bugs at varnish-cache.org
Mon Aug 1 12:33:17 CEST 2011
#965: Restarting a request in vcl_miss causes Varnish client crash.
-------------------+--------------------------------------------------------
Reporter: david | Type: defect
Status: new | Priority: normal
Milestone: | Component: build
Version: 3.0.0 | Severity: normal
Keywords: |
-------------------+--------------------------------------------------------
Description changed by phk:
Old description:
> Hello!
>
> I've done extensive testing on this, and I believe I've found a bug in
> Varnish. The VCL below loads correctly, but causes the Varnish client to
> crash after 1-2 requests. The backstory is available in the forums here
> https://www.varnish-cache.org/forum/topic/65 - if you have any questions
> that are not answered in that post, please ask away; I'd love to explain
> and make more sense of what I'm trying to do. This isn't the exact VCL
> I'd use in production, it is a minimalistic version that is able to
> reproduce the crash:
>
> sub vcl_recv {
> if (!req.http.X-Forwarded-For) { set req.http.X-Forwarded-For =
> client.ip; }
> if (req.http.X-Banned == "check") { remove req.http.X-Banned; }
> elseif (req.restarts == 0) {
> set req.http.X-Banned = "check";
> return (lookup);
> }
> }
>
> sub vcl_hash {
> ## Check if they have a ban in the cache, or if they are going to be
> banned in cache.
> if (req.http.X-Banned) {
> hash_data(req.http.X-Forwarded-For);
> return (hash);
> }
> }
>
> sub vcl_error {
> if (obj.status == 988) { return (restart); }
> }
>
> sub vcl_miss {
> if (req.http.X-Banned == "check") { error 988 "restarting"; }
> }
>
> This is a successful request. After this request, the second request will
> not work (Varnish restarts):
> 0 Debug - "VCL_error(988, restarting)"
> 9 BackendOpen b production[47] 172.21.4.182 41813 172.21.4.111 80
> 9 TxRequest b GET
> 9 TxURL b http://www.site.com/
> 9 TxProtocol b HTTP/1.1
> 9 TxHeader b User-Agent: curl/7.19.7 (universal-apple-darwin10.0)
> libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
> 9 TxHeader b Host: www.site.com
> 9 TxHeader b Accept: */*
> 9 TxHeader b Proxy-Connection: Keep-Alive
> 9 TxHeader b X-Forwarded-For: 127.0.0.1
> 9 TxHeader b X-Varnish: 746583022
> 9 TxHeader b Accept-Encoding: gzip
> 9 RxProtocol b HTTP/1.1
> 9 RxStatus b 200
> 9 RxResponse b OK
> 9 RxHeader b Date: Thu, 16 Jun 2011 23:45:54 GMT
> 9 RxHeader b Server: Apache/2.2.3 (CentOS)
> 9 RxHeader b Cache-Control: private, proxy-revalidate
> 9 RxHeader b ETag: "9658bc1e80033b21277323e725948c91"
> 9 RxHeader b Content-Encoding: gzip
> 9 RxHeader b Vary: Accept-Encoding
> 9 RxHeader b Content-length: 11452
> 9 RxHeader b Content-Type: text/html; charset=utf-8
> 9 RxHeader b Content-Language: en
> 9 Fetch_Body b 4 0 1
> 9 Length b 11452
> 9 BackendReuse b production[47]
> 3 SessionOpen c 127.0.0.1 1204 :80
> 3 ReqStart c 127.0.0.1 1204 746583022
> 3 RxRequest c HEAD
> 3 RxURL c http://www.site.com/
> 3 RxProtocol c HTTP/1.1
> 3 RxHeader c User-Agent: curl/7.19.7 (universal-apple-darwin10.0)
> libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
> 3 RxHeader c Host: www.site.com
> 3 RxHeader c Accept: */*
> 3 RxHeader c Proxy-Connection: Keep-Alive
> 3 VCL_call c recv lookup
> 3 VCL_call c hash
> 3 Hash c 127.0.0.1
> 3 VCL_return c hash
> 3 VCL_call c miss error
> 3 VCL_call c error restart
> 3 VCL_call c recv lookup
> 3 VCL_call c hash
> 3 Hash c http://www.site.com/
> 3 Hash c www.site.com
> 3 VCL_return c hash
> 3 VCL_call c miss fetch
> 3 Backend c 9 production production[47]
> 3 TTL c 746583022 RFC 300 1308267955 0 0 0 0
> 3 VCL_call c fetch deliver
> 3 ObjProtocol c HTTP/1.1
> 3 ObjResponse c OK
> 3 ObjHeader c Date: Thu, 16 Jun 2011 23:45:54 GMT
> 3 ObjHeader c Server: Apache/2.2.3 (CentOS)
> 3 ObjHeader c Cache-Control: private, proxy-revalidate
> 3 ObjHeader c ETag: "9658bc1e80033b21277323e725948c91"
> 3 ObjHeader c Content-Encoding: gzip
> 3 ObjHeader c Vary: Accept-Encoding
> 3 ObjHeader c Content-Type: text/html; charset=utf-8
> 3 ObjHeader c Content-Language: en
> 3 Gzip c u F - 11452 46817 80 80 91551
> 3 VCL_call c deliver deliver
> 3 TxProtocol c HTTP/1.1
> 3 TxStatus c 200
> 3 TxResponse c OK
> 3 TxHeader c Server: Apache/2.2.3 (CentOS)
> 3 TxHeader c Cache-Control: private, proxy-revalidate
> 3 TxHeader c ETag: "9658bc1e80033b21277323e725948c91"
> 3 TxHeader c Vary: Accept-Encoding
> 3 TxHeader c Content-Type: text/html; charset=utf-8
> 3 TxHeader c Content-Language: en
> 3 TxHeader c Date: Thu, 16 Jun 2011 23:45:54 GMT
> 3 TxHeader c X-Varnish: 746583022
> 3 TxHeader c Age: 0
> 3 TxHeader c Via: 1.1 varnish
> 3 TxHeader c Connection: keep-alive
> 3 Length c 0
> 3 ReqEnd c 746583022 1308267954.333659887 1308267954.527986050
> 0.000048876 0.194267035 0.000059128
> 3 Debug c herding
> 3 SessionClose c no request
> 3 StatSess c 127.0.0.1 1204 0 1 1 0 0 1 344 0
> 0 Backend_health - production[33] Still healthy ------- 4 3 8
> 0.000000 0.000272
> 3 SessionOpen c 172.21.4.16 57711 :80
> 3 SessionClose c EOF
>
> Regards,
> -david
New description:
Hello!
I've done extensive testing on this, and I believe I've found a bug in
Varnish. The VCL below loads correctly, but causes the Varnish client to
crash after 1-2 requests. The backstory is available in the forums here
https://www.varnish-cache.org/forum/topic/65 - if you have any questions
that are not answered in that post, please ask away; I'd love to explain
and make more sense of what I'm trying to do. This isn't the exact VCL I'd
use in production, it is a minimalistic version that is able to reproduce
the crash:
{{{
sub vcl_recv {
if (!req.http.X-Forwarded-For) { set req.http.X-Forwarded-For =
client.ip; }
if (req.http.X-Banned == "check") { remove req.http.X-Banned; }
elseif (req.restarts == 0) {
set req.http.X-Banned = "check";
return (lookup);
}
}
sub vcl_hash {
## Check if they have a ban in the cache, or if they are going to be
banned in cache.
if (req.http.X-Banned) {
hash_data(req.http.X-Forwarded-For);
return (hash);
}
}
sub vcl_error {
if (obj.status == 988) { return (restart); }
}
sub vcl_miss {
if (req.http.X-Banned == "check") { error 988 "restarting"; }
}
This is a successful request. After this request, the second request will
not work (Varnish restarts):
0 Debug - "VCL_error(988, restarting)"
9 BackendOpen b production[47] 172.21.4.182 41813 172.21.4.111 80
9 TxRequest b GET
9 TxURL b http://www.site.com/
9 TxProtocol b HTTP/1.1
9 TxHeader b User-Agent: curl/7.19.7 (universal-apple-darwin10.0)
libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
9 TxHeader b Host: www.site.com
9 TxHeader b Accept: */*
9 TxHeader b Proxy-Connection: Keep-Alive
9 TxHeader b X-Forwarded-For: 127.0.0.1
9 TxHeader b X-Varnish: 746583022
9 TxHeader b Accept-Encoding: gzip
9 RxProtocol b HTTP/1.1
9 RxStatus b 200
9 RxResponse b OK
9 RxHeader b Date: Thu, 16 Jun 2011 23:45:54 GMT
9 RxHeader b Server: Apache/2.2.3 (CentOS)
9 RxHeader b Cache-Control: private, proxy-revalidate
9 RxHeader b ETag: "9658bc1e80033b21277323e725948c91"
9 RxHeader b Content-Encoding: gzip
9 RxHeader b Vary: Accept-Encoding
9 RxHeader b Content-length: 11452
9 RxHeader b Content-Type: text/html; charset=utf-8
9 RxHeader b Content-Language: en
9 Fetch_Body b 4 0 1
9 Length b 11452
9 BackendReuse b production[47]
3 SessionOpen c 127.0.0.1 1204 :80
3 ReqStart c 127.0.0.1 1204 746583022
3 RxRequest c HEAD
3 RxURL c http://www.site.com/
3 RxProtocol c HTTP/1.1
3 RxHeader c User-Agent: curl/7.19.7 (universal-apple-darwin10.0)
libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
3 RxHeader c Host: www.site.com
3 RxHeader c Accept: */*
3 RxHeader c Proxy-Connection: Keep-Alive
3 VCL_call c recv lookup
3 VCL_call c hash
3 Hash c 127.0.0.1
3 VCL_return c hash
3 VCL_call c miss error
3 VCL_call c error restart
3 VCL_call c recv lookup
3 VCL_call c hash
3 Hash c http://www.site.com/
3 Hash c www.site.com
3 VCL_return c hash
3 VCL_call c miss fetch
3 Backend c 9 production production[47]
3 TTL c 746583022 RFC 300 1308267955 0 0 0 0
3 VCL_call c fetch deliver
3 ObjProtocol c HTTP/1.1
3 ObjResponse c OK
3 ObjHeader c Date: Thu, 16 Jun 2011 23:45:54 GMT
3 ObjHeader c Server: Apache/2.2.3 (CentOS)
3 ObjHeader c Cache-Control: private, proxy-revalidate
3 ObjHeader c ETag: "9658bc1e80033b21277323e725948c91"
3 ObjHeader c Content-Encoding: gzip
3 ObjHeader c Vary: Accept-Encoding
3 ObjHeader c Content-Type: text/html; charset=utf-8
3 ObjHeader c Content-Language: en
3 Gzip c u F - 11452 46817 80 80 91551
3 VCL_call c deliver deliver
3 TxProtocol c HTTP/1.1
3 TxStatus c 200
3 TxResponse c OK
3 TxHeader c Server: Apache/2.2.3 (CentOS)
3 TxHeader c Cache-Control: private, proxy-revalidate
3 TxHeader c ETag: "9658bc1e80033b21277323e725948c91"
3 TxHeader c Vary: Accept-Encoding
3 TxHeader c Content-Type: text/html; charset=utf-8
3 TxHeader c Content-Language: en
3 TxHeader c Date: Thu, 16 Jun 2011 23:45:54 GMT
3 TxHeader c X-Varnish: 746583022
3 TxHeader c Age: 0
3 TxHeader c Via: 1.1 varnish
3 TxHeader c Connection: keep-alive
3 Length c 0
3 ReqEnd c 746583022 1308267954.333659887 1308267954.527986050
0.000048876 0.194267035 0.000059128
3 Debug c herding
3 SessionClose c no request
3 StatSess c 127.0.0.1 1204 0 1 1 0 0 1 344 0
0 Backend_health - production[33] Still healthy ------- 4 3 8 0.000000
0.000272
3 SessionOpen c 172.21.4.16 57711 :80
3 SessionClose c EOF
}}}
Regards,
-david
--
--
Ticket URL: <http://varnish-cache.org/trac/ticket/965#comment:1>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list