[Varnish] #1494: panic on retry in vcl_backend_response

[Varnish]

#1494: panic on retry in vcl_backend_response
-------------------------+------------------------
 Reporter:  g.gerritsen  |       Owner:
     Type:  defect       |      Status:  Need info
 Priority:  normal       |   Milestone:
Component:  build        |     Version:  4.0.0
 Severity:  normal       |  Resolution:
 Keywords:               |
-------------------------+------------------------

Comment (by g.gerritsen):

 On receiving the request http://monitor.nl.local/500.php (simple php
 script returning status 500) using the 1494.vcl,

 varnishlog tells me

 {{{#!python


 *   << BeReq    >> 3
 -   Begin          bereq 2 fetch
 -   Timestamp      Start: 1399905220.620958 0.000000 0.000000
 -   BereqMethod    GET
 -   BereqURL       /500.php
 -   BereqProtocol  HTTP/1.1
 -   BereqHeader    Host: monitor.nl.local
 -   BereqHeader    User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:29.0)
 Gecko/20100101 Firefox/29.0
 -   BereqHeader    Accept:
 text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
 -   BereqHeader    Accept-Language: en-US,en;q=0.5
 -   BereqHeader    X-Forwarded-For: 172.16.10.136
 -   BereqHeader    Accept-Encoding: gzip
 -   BereqHeader    X-Varnish: 3
 -   VCL_call       BACKEND_FETCH
 -   VCL_return     fetch
 -   BackendOpen    17 default(172.16.10.224,,80) 10.16.19.81 25819
 -   Backend        17 default default(172.16.10.224,,80)
 -   Timestamp      Bereq: 1399905220.631030 0.010072 0.010072
 -   Timestamp      Beresp: 1399905220.643308 0.022349 0.012277
 -   BerespProtocol HTTP/1.1
 -   BerespStatus   500
 -   BerespResponse Internal Server Error
 -   BerespHeader   Date: Mon, 12 May 2014 14:33:40 GMT
 -   BerespHeader   Server: Apache/2.2.15 (CentOS)
 -   BerespHeader   X-Powered-By: PHP/5.4.27
 -   BerespHeader   Content-Length: 0
 -   BerespHeader   Connection: close
 -   BerespHeader   Content-Type: text/html; charset=UTF-8
 -   TTL            RFC -1 -1 -1 1399905221 1399905221 1399905220 0 0
 -   VCL_call       BACKEND_RESPONSE
 -   VCL_Log        retrying
 -   VCL_return     retry
 -   BackendClose   17 default(172.16.10.224,,80)
 -   Timestamp      Retry: 1399905220.643467 0.022509 0.000159
 -   Link           bereq 32769 retry
 -   End

 *   << Session  >> 1
 -   Begin          sess 0 HTTP/1
 -   SessOpen       172.16.10.136 52579 :80 10.16.19.81 80
 1399905220.620053 12
 -   Link           req 2 rxreq
 -   VSL            flush
 -   End            synth

 *   << BeReq    >> 32769
 -   Begin          bereq 3 retry
 -   Timestamp      Start: 1399905220.643467 0.022509 0.000000
 -   VSL            flush
 -   End            synth

 Log abandoned
 Log reaquired

 }}}

 panic.show
 {{{#!python
 #  varnishadm panic.show
 Last panic at: Mon, 12 May 2014 14:33:41 GMT
 Assert error in vbf_stp_startfetch(), cache/cache_fetch.c line 258:
   Condition((bo->should_close) == 0) not true.
 thread = (cache-worker)
 ident =
 Linux,2.6.32-431.11.2.el6.x86_64,x86_64,-smalloc,-smalloc,-hcritbit,epoll
 Backtrace:
   0x43a536: /usr/sbin/varnishd() [0x43a536]
   0x43a846: /usr/sbin/varnishd() [0x43a846]
   0x422e26: /usr/sbin/varnishd() [0x422e26]
   0x425273: /usr/sbin/varnishd() [0x425273]
   0x43c343: /usr/sbin/varnishd(Pool_Work_Thread+0x416) [0x43c343]
   0x454ce2: /usr/sbin/varnishd() [0x454ce2]
   0x454e0b: /usr/sbin/varnishd(WRK_thread+0x27) [0x454e0b]
   0x7f0866ef19d1: /lib64/libpthread.so.0(+0x79d1) [0x7f0866ef19d1]
   0x7f0866c3eb6d: /lib64/libc.so.6(clone+0x6d) [0x7f0866c3eb6d]
   busyobj = 0x7f0855828020 {
     ws = 0x7f08558280e8 {
       id = "bo",
       {s,f,r,e} = {0x7f0855829ff0,+544,(nil),+57392},
     },
   refcnt = 2
   retries = 1
   failed = 0
   state = 1
     is_do_stream
     is_should_close
     bodystatus = 3 (length),
     },
     http[bereq] = {
       ws = 0x7f08558280e8[bo]
         "GET",
         "/500.php",
         "HTTP/1.1",
         "Host: monitor.nl.local",
         "User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:29.0)
 Gecko/20100101 Firefox/29.0",
         "Accept:
 text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8",
         "Accept-Language: en-US,en;q=0.5",
         "X-Forwarded-For: 172.16.10.136",
         "Accept-Encoding: gzip",
         "X-Varnish: 3",
     },
     http[beresp] = {
       ws = 0x7f08558280e8[bo]
         "HTTP/1.1",
         "500",
         "Internal Server Error",
         "Date: Mon, 12 May 2014 14:33:40 GMT",
         "Server: Apache/2.2.15 (CentOS)",
         "X-Powered-By: PHP/5.4.27",
         "Content-Length: 0",
         "Connection: close",
         "Content-Type: text/html; charset=UTF-8",
     },
     ws = 0x7f0855828270 { BAD_MAGIC(0x00000000) },
     },
   objcore (FETCH) = 0x7f0855866080 {
     refcnt = 2
     flags = 0x2
     objhead = 0x7f0855868080
   }
   }

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1494#comment:2>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator