[Varnish] #1463: Assert in cnt_lookup(), cache/cache_req_fsm.c line 417

[Varnish]

#1463: Assert in cnt_lookup(), cache/cache_req_fsm.c line 417
----------------------+-------------------
 Reporter:  lkarsten  |      Owner:
     Type:  defect    |     Status:  new
 Priority:  normal    |  Milestone:
Component:  varnishd  |    Version:  trunk
 Severity:  normal    |   Keywords:
----------------------+-------------------
 We tested current master (6dc740f00) in production, serving about
 1400req/s.

 On a 2 hour run we saw this assert at the beginning. No asserts after the
 cache was warm.

 On a semi-related note, there was significant CPU usage (80-100% on 8
 cores) when the cache was filling. Fell
 down to 300-450% when steady state was attained.

 {{{
 Last panic at: Thu, 27 Mar 2014 12:01:27 GMT
 Assert error in cnt_lookup(), cache/cache_req_fsm.c line 417:
   Condition((oc->busyobj) == 0) not true.
 thread = (cache-worker)
 ident =
 Linux,2.6.32-431.5.1.el6.x86_64,x86_64,-smalloc,-smalloc,-hcritbit,epoll
 Backtrace:
   0x4399d2: /usr/sbin/varnishd() [0x4399d2]
   0x439ce2: /usr/sbin/varnishd() [0x439ce2]
   0x43dc5f: /usr/sbin/varnishd() [0x43dc5f]
   0x43fca8: /usr/sbin/varnishd(CNT_Request+0x441) [0x43fca8]
   0x432be0: /usr/sbin/varnishd(HTTP1_Session+0x429) [0x432be0]
   0x442c5d: /usr/sbin/varnishd() [0x442c5d]
   0x442f28: /usr/sbin/varnishd() [0x442f28]
   0x43b547: /usr/sbin/varnishd(Pool_Work_Thread+0x416) [0x43b547]
   0x453f94: /usr/sbin/varnishd() [0x453f94]
   0x4540bd: /usr/sbin/varnishd(WRK_thread+0x27) [0x4540bd]
 req = 0x7f3718caf910 {
   sp = 0x7f36e0452b70, vxid = 1079805327,  step = R_STP_LOOKUP,
   req_body = R_BODY_NONE,
   restarts = 0, esi_level = 0
   sp = 0x7f36e0452b70 {
     fd = 1158, vxid = 5573417,
     client = 85.166.x.x 62664,
     step = S_STP_WORKING,
   },
   worker = 0x7f375c1dfc30 {
     ws = 0x7f375c1dfe30 {
       id = "wrk",
       {s,f,r,e} = {0x7f375c1df410,0x7f375c1df410,(nil),+2048},
     },
   VCL::method = 0x0,
   VCL::return = deliver,
   },
   ws = 0x7f3718cafa98 {
     id = "req",
     {s,f,r,e} = {0x7f3718cb18f0,+520,(nil),+2088992},
   },
   http[req] = {
     ws = 0x7f3718cafa98[req]
       "GET",
       "XXX"
       "HTTP/1.1",
       "Accept: image/png, image/svg+xml, image/*;q=0.8, */*;q=0.5",
       "Referer: http://www.XXX/",
       "Accept-Language: nb-NO",
       "User-Agent: Mozilla/5.0 (Windows NT 6.1; Trident/7.0; rv:11.0) like
 Gecko",
       "Host: XXX",
       "DNT: 1",
       "Connection: Keep-Alive",
       "X-Forwarded-For: 85.166.xx.xx",
       "Accept-Encoding: gzip",
       "X-Debug-obj-ttl: -1.038",
   },
   vcl = {
     srcname = {
       "input",
       "Default",
       "xx",
       "xx",
       "xx",
       "xx",
     },
   },
   busyobj = 0x7f36f80f0930 {
     ws = 0x7f36f80f09f8 {
       id = "bo",
       {s,f,r,e} = {0x7f36f80f28e0,+1432,(nil),+57424},
     },
   refcnt = 1
   retries = 0
   failed = 0
   state = 2
     is_do_stream
     is_is_gzip
     bodystatus = 3 (length),
     },
     http[bereq] = {
       ws = 0x7f36f80f09f8[bo]
         "GET",
         "XXX",
         "HTTP/1.1",
         "Host: XXX",
         "Accept: image/webp,*/*;q=0.8",
         "User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64)
 AppleWebKit/537.36 (KHTML, like Gecko) Chrome/33.0.1750.154
 Safari/537.36",
         "Referer: http://www.YYYY",
         "Accept-Language: nb-NO,nb;q=0.8,no;q=0.6,nn;q=0.4,en-
 US;q=0.2,en;q=0.2",
         "X-Forwarded-For: 217.144.xx.xx",
         "Accept-Encoding: gzip",
         "X-Debug-obj-ttl: -1.005",
         "X-Varnish: 13797825",
     },
     http[beresp] = {
       ws = 0x7f36f80f09f8[bo]
         "HTTP/1.1",
         "404",
         "Not Found",
         "X-Trace-App: xx",
         "Cache-Control: max-age=60, xxx",
         "Access-Control-Allow-Origin: *",
         "Content-Type: text/html; charset=iso-8859-1",
         "Server: Jetty(6.1.25)",
         "x-channel-maxage: 60",
         "X-Src-Webcache: xx",
         "Content-Encoding: gzip",
         "Content-Length: 95",
         "Accept-Ranges: bytes",
         "Date: Thu, 27 Mar 2014 12:01:26 GMT",
         "X-Varnish: 2835180224 2835179698",
         "Age: 5",
         "Via: 1.1 varnish",
         "Connection: keep-alive",
         "X-Trace-Cache: xxx",
         "X-Trace-CacheTMP: ",
     },
     ws = 0x7f36f80f0b60 {
       id = "obj",
       {s,f,r,e} = {0x7f36b444d360,+728,(nil),+728},
     },
   objcore (FETCH) = 0x7f364da34060 {
     refcnt = 3
     flags = 0x0
     objhead = 0x7f3664236b40
   }
   obj (FETCH) = 0x7f36b444d140 {
     vxid = 2161281473,
     http[obj] = {
       ws = 0x7f36f80f0b60[obj]
         "HTTP/1.1",
         "404",
         "Not Found",
         "X-Trace-App: xxx",
         "Cache-Control: max-age=60, xxx",
         "Access-Control-Allow-Origin: *",
         "Content-Type: text/html; charset=iso-8859-1",
         "Server: Jetty(6.1.25)",
         "x-channel-maxage: 60",
         "X-Src-Webcache: xx",
         "Content-Encoding: gzip",
         "Date: Thu, 27 Mar 2014 12:01:26 GMT",
         "X-Varnish: 2835180224 2835179698",
         "Via: 1.1 varnish",
         "X-Trace-Cache: xx",
         "X-Trace-CacheTMP: ",
     },
     len = 0,
     store = {
       0 {
       },
     },
   },
   }
   obj (REQ) = 0x7f36b444d140 {
     vxid = 2161281473,
     http[obj] = {
       ws = 0x7f36f80f0b60[obj]
         "HTTP/1.1",
         "404",
         "Not Found",
         "X-Trace-App: xx",
         "Cache-Control: max-age=60, xx",
         "Access-Control-Allow-Origin: *",
         "Content-Type: text/html; charset=iso-8859-1",
         "Server: Jetty(6.1.25)",
         "x-channel-maxage: 60",
         "X-Src-Webcache: xx",
         "Content-Encoding: gzip",
         "Date: Thu, 27 Mar 2014 12:01:26 GMT",
         "X-Varnish: 2835180224 2835179698",
         "Via: 1.1 varnish",
         "X-Trace-Cache: xx",
         "X-Trace-CacheTMP: ",
     },
     len = 0,
     store = {
       0 {
       },
     },
   },
 },

 }}}

-- 
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1463>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator