[Varnish] #965: Restarting a request in vcl_miss causes Varnish client crash.

Varnish varnish-bugs at varnish-cache.org
Tue Aug 2 14:08:09 CEST 2011


#965: Restarting a request in vcl_miss causes Varnish client crash.
--------------------+-------------------------------------------------------
 Reporter:  david   |       Owner:  tfheen
     Type:  defect  |      Status:  new   
 Priority:  normal  |   Milestone:        
Component:  build   |     Version:  3.0.0 
 Severity:  normal  |    Keywords:        
--------------------+-------------------------------------------------------
Description changed by tfheen:

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:3>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator



More information about the varnish-bugs mailing list