[Varnish] #162: Varnish trunk dies with assert error in SES_Delete()

[Varnish]

#162: Varnish trunk dies with assert error in SES_Delete()
---------------------------------------------------------+------------------
 Reporter:  anders                                       |        Owner:  des          
     Type:  defect                                       |       Status:  reopened     
 Priority:  high                                         |    Milestone:  Varnish 1.1.2
Component:  varnishd                                     |      Version:  1.1          
 Severity:  normal                                       |   Resolution:               
 Keywords:  varnishd core dump SES_Delete cache_session  |  
---------------------------------------------------------+------------------
Changes (by anders):

  * status:  closed => reopened
  * resolution:  fixed =>

Comment:

 I am running trunk/2415 with:

 - madvise patch (http://anders.fupp.hnet/test/varnishd_madvise.diff)

 - mmap patch (http://anders.fupp.net/test/varnish-patch-storage-mmap-sync)

 - polling, instead of kqueue (as kqueue gives me other crashes as
 mentioned in ticket 173)

 - obj.grace (vcl_fetch) and req.grace (vcl_recv) set to 5 minutes.

 And then I got a crash:

 {{{
 Child said (2, 934): <<Assert error in SES_Delete(), cache_session.c line
 339:
   Condition((sp->vcl) == 0) not true.
 >>
 Child said (2, 934): <<  errno = 54 (Connection reset by peer)
 >>
 Cache child died pid=934 status=0x86
 }}}

 This was after collecting around 600000 objects and around 20 GB data in
 the cache, running for a little less than 2 hours. This is on a server
 with 48 GB RAM, and 8 CPU cores. I did one change before doing the test
 here: added four more disks, making Varnish use 5 50 GB storage files on 5
 different RAID volumes - having a total disk cache of 250 GB.

 The backtrace:

 {{{
 (gdb) bt
 #0  0x0000000800d17fec in thr_kill () from /lib/libc.so.7
 #1  0x0000000800da1c5b in abort () from /lib/libc.so.7
 #2  0x0000000800674cf2 in lbv_assert (func=Could not find the frame base
 for "lbv_assert".
 ) at assert.c:63
 #3  0x000000000041dcf4 in SES_Delete (sp=0x4690879008) at
 cache_session.c:339
 #4  0x000000000041b62a in WRK_QueueSession (sp=0x4690879008)
     at cache_pool.c:318
 #5  0x000000000041568e in hsh_rush (oh=0x46b10a12e0) at cache_hash.c:289
 #6  0x0000000000415818 in HSH_Unbusy (o=0x8ea490000) at cache_hash.c:311
 #7  0x000000000040fc33 in cnt_fetch (sp=0x4695392008) at
 cache_center.c:370
 #8  0x00000000004117aa in CNT_Session (sp=0x4695392008) at steps.h:41
 #9  0x000000000041acad in wrk_do_one (w=0x7ffefe1f5ae0) at
 cache_pool.c:193
 #10 0x000000000041b1b0 in wrk_thread (priv=0x800f11200) at
 cache_pool.c:247
 #11 0x0000000800a9fa88 in pthread_getprio () from /lib/libthr.so.3
 #12 0x00007ffefdff6000 in ?? ()
 Cannot access memory at address 0x7ffefe1f6000
 (gdb) frame 3
 #3  0x000000000041dcf4 in SES_Delete (sp=0x4690879008) at
 cache_session.c:339
 339             AZ(sp->vcl);
 (gdb) print *sp
 $1 = {magic = 741317722, fd = -1, id = 11357, xid = 498268411, restarts =
 0,
   esis = 0, wrk = 0x7ffe8321fae0, sockaddrlen = 16, mysockaddrlen = 128,
   sockaddr = 0x4690879680, mysockaddr = 0x4690879700,
   addr = 0x4690879780 "84.209.33.147", port = 0x469087978e "12398",
   srcaddr = 0x4699a24770, doclose = 0x0, http = 0x46908791d8,
   http0 = 0x4690879420, ws = {{magic = 905626964, id = 0x4391f8 "sess",
       s = 0x4690879780 "84.209.33.147",
       f = 0x46908799c1
 "929a1199303665640:lv=1201891478937:ss=1201891469875; RMFD=011JL0rM", r =
 0x0, e = 0x469087d780 ""}}, ws_ses = 0x4690879794 "GET",
   ws_req = 0x4690879989 "", htc = {{magic = 1041886673, fd = 11357,
       ws = 0x4690879070, rxbuf = {b = 0x4690879794 "GET",
         e = 0x4690879989 ""}, pipeline = {b = 0x0, e = 0x0}}},
   t_open = 1201891640.1903741, t_req = 1201891640.226583,
   t_resp = nan(0x8000000000000), t_end = 1201891651.267303, grace = 300,
   step = STP_LOOKUP, cur_method = 0, handling = 4, sendbody = 0 '\0',
   wantbody = 1 '\001', err_code = 0, err_reason = 0x0, list = {
     vtqe_next = 0x0, vtqe_prev = 0x46b10a1318}, backend = 0x800f14140,
   bereq = 0x0, obj = 0x0, objhead = 0x46b10a12e0, vcl = 0x4689c03e20,
   mem = 0x4690879000, workreq = {list = {vtqe_next = 0x0, vtqe_prev =
 0x0},
     sess = 0x4690879008}, acct = {first = 1201891640.1903741, sess = 1,
     req = 1, pipe = 0, pass = 0, fetch = 0, hdrbytes = 0, bodybytes = 0},
   nhashptr = 6, ihashptr = 4, lhashptr = 54, hashptr = 0x4690879990}
 }}}

-- 
Ticket URL: <http://varnish.projects.linpro.no/ticket/162#comment:22>
Varnish <http://varnish.projects.linpro.no/>
The Varnish HTTP Accelerator