[Varnish] #667: bug with cacheable false in vcl_fetch

[Varnish]

#667: bug with cacheable false in vcl_fetch
----------------------+-----------------------------------------------------
 Reporter:  kali      |       Owner:  phk  
     Type:  defect    |      Status:  new  
 Priority:  normal    |   Milestone:       
Component:  varnishd  |     Version:  trunk
 Severity:  major     |    Keywords:       
----------------------+-----------------------------------------------------
 Setting bereq.cacheable to false in vcl_fetch let requests identical to
 the one being fetch deadlocked.

 VCL:
 {{{
 backend b { .host = "localhost"; .port = "4567"; }
 sub vcl_fetch { set beresp.cacheable = false; }
 }}}

 Backend: it just has to be something slow
 {{{
 ruby -e 'require "rubygems" ; require "sinatra"; get "/" do sleep 30;
 "Hello there" end'
 }}}

 Varnish:
 {{{
 varnishd -a :9000  -f /tmp/test.vcl -n /tmp -p default_gracet=0
 }}}

 Client:
 {{{
 17/03 20:18 ~% curl http://localhost:9000 &
 [1] 2346
 17/03 20:18 ~% curl http://localhost:9000 &
 [2] 2347
 17/03 20:18 ~% Hello there
 [1]  - 2346 done       curl http://localhost:9000
 }}}

 Only the first query is passed to the backend, and returns as expected
 after 30 seconds, the second stays in varnish cyberspace forever. It is
 not send to the backend, neither on reception of the request, nor when the
 reponse comes back.

 Varnishlog:
 {{{
    13 SessionOpen  c ::1 48067 :9000
    13 ReqStart     c ::1 48067 265112395
    13 RxRequest    c GET
    13 RxURL        c /
    13 RxProtocol   c HTTP/1.1
    13 RxHeader     c User-Agent: curl/7.18.2 (x86_64-pc-linux-gnu)
 libcurl/7.18.2 OpenSSL/0.9.8g zlib/1.2.3.3 libidn/1.10
    13 RxHeader     c Host: localhost:9000
    13 RxHeader     c Accept: */*
    13 VCL_call     c recv
    13 VCL_return   c lookup
    13 VCL_call     c hash
    13 VCL_return   c hash
    13 VCL_call     c miss
    13 VCL_return   c fetch
    14 BackendOpen  b b 127.0.0.1 47798 127.0.0.1 4567
    13 Backend      c 14 b b
    14 TxRequest    b GET
    14 TxURL        b /
    14 TxProtocol   b HTTP/1.1
    14 TxHeader     b User-Agent: curl/7.18.2 (x86_64-pc-linux-gnu)
 libcurl/7.18.2 OpenSSL/0.9.8g zlib/1.2.3.3 libidn/1.10
    14 TxHeader     b Host: localhost:9000
    14 TxHeader     b Accept: */*
    14 TxHeader     b X-Forwarded-For: ::1
    14 TxHeader     b X-Varnish: 265112395
     0 CLI          - Rd ping
     0 CLI          - Wr 200 PONG 1268857099 1.0
    15 SessionOpen  c ::1 48069 :9000
    15 ReqStart     c ::1 48069 265112396
    15 RxRequest    c GET
    15 RxURL        c /
    15 RxProtocol   c HTTP/1.1
    15 RxHeader     c User-Agent: curl/7.18.2 (x86_64-pc-linux-gnu)
 libcurl/7.18.2 OpenSSL/0.9.8g zlib/1.2.3.3 libidn/1.10
    15 RxHeader     c Host: localhost:9000
    15 RxHeader     c Accept: */*
    15 VCL_call     c recv
    15 VCL_return   c lookup
    15 VCL_call     c hash
    15 VCL_return   c hash
     0 CLI          - Rd ping
     0 CLI          - Wr 200 PONG 1268857102 1.0
 [...]
     0 CLI          - Wr 200 PONG 1268857126 1.0
    14 RxProtocol   b HTTP/1.1
    14 RxStatus     b 200
    14 RxResponse   b OK
    14 RxHeader     b Connection: Keep-Alive
    14 RxHeader     b Content-Type: text/html
    14 RxHeader     b Date: Wed, 17 Mar 2010 20:18:49 GMT
    14 RxHeader     b Server: WEBrick/1.3.1 (Ruby/1.8.7/2008-08-11)
    14 RxHeader     b Content-Length: 11
    13 TTL          c 265112395 RFC 120 1268857129 0 0 0 0
    13 VCL_call     c fetch
    13 VCL_return   c pass
    13 ObjProtocol  c HTTP/1.1
    13 ObjStatus    c 200
    13 ObjResponse  c OK
    13 ObjHeader    c Content-Type: text/html
    13 ObjHeader    c Date: Wed, 17 Mar 2010 20:18:49 GMT
    13 ObjHeader    c Server: WEBrick/1.3.1 (Ruby/1.8.7/2008-08-11)
    14 BackendReuse b b
    13 Length       c 11
    13 VCL_call     c deliver
    13 VCL_return   c deliver
    13 TxProtocol   c HTTP/1.1
    13 TxStatus     c 200
    13 TxResponse   c OK
    13 TxHeader     c Content-Type: text/html
    13 TxHeader     c Server: WEBrick/1.3.1 (Ruby/1.8.7/2008-08-11)
    13 TxHeader     c Content-Length: 11
    13 TxHeader     c Date: Wed, 17 Mar 2010 20:18:49 GMT
    13 TxHeader     c X-Varnish: 265112395
    13 TxHeader     c Age: 0
    13 TxHeader     c Via: 1.1 varnish
    13 TxHeader     c Connection: keep-alive
    13 ReqEnd       c 265112395 1268857099.029391527 1268857129.035051823
 0.000235796 30.005545616 0.000114679
    13 SessionClose c EOF
    13 ReqEnd       c 0 1268857129.035354376 1268857129.035354376
 0.000302553 0.000000000 0.000000000
    13 StatSess     c ::1 48067 30 1 1 0 0 1 221 11
     0 CLI          - Rd ping
     0 CLI          - Wr 200 PONG 1268857129 1.0
 }}}

 I tried changing default_grace to 0, but it did not change anything.

-- 
Ticket URL: <http://www.varnish-cache.org/ticket/667>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator