[Varnish] #886: Ban-related crashes

[Varnish]

#886: Ban-related crashes
----------------------+-----------------------------------------------------
 Reporter:  kristian  |       Owner:                 
     Type:  defect    |      Status:  new            
 Priority:  normal    |   Milestone:  Varnish 3.0 dev
Component:  build     |     Version:  trunk          
 Severity:  normal    |    Keywords:                 
----------------------+-----------------------------------------------------
 I'm getting crashes in both the ban lurker and through esi-parsing (that
 might be co-incidental).

 It all boils down to:

 {{{

 Program terminated with signal 11, Segmentation fault.
 #0  ban_check_object (o=0x2aaab0861800, sp=0x2aaaab000008, has_req=0) at
 cache_ban.c:448
 448                     if (b->flags & BAN_F_GONE)
 (gdb) bt
 #0  ban_check_object (o=0x2aaab0861800, sp=0x2aaaab000008, has_req=0) at
 cache_ban.c:448
 #1  0x0000000000413549 in ban_lurker (sp=0x2aaaab000008, priv=<value
 optimized out>) at cache_ban.c:544
 #2  0x000000000042c69c in wrk_bgthread (arg=0x2af972b043c0) at
 cache_pool.c:581
 #3  0x0000003aac40673d in start_thread () from /lib64/libpthread.so.0
 #4  0x0000003aabcd3f6d in clone () from /lib64/libc.so.6
 }}}

 Or, in the case of "esi"/request-path:

 {{{
 Program terminated with signal 11, Segmentation fault.
 #0  ban_check_object (o=0x2aaab0099900, sp=0x2aaab3d00008, has_req=1) at
 cache_ban.c:448
 448                     if (b->flags & BAN_F_GONE)
 (gdb) bt
 #0  ban_check_object (o=0x2aaab0099900, sp=0x2aaab3d00008, has_req=1) at
 cache_ban.c:448
 #1  0x000000000042449c in HSH_Lookup (sp=0x2aaab3d00008, poh=0x527e5578)
 at cache_hash.c:359
 #2  0x0000000000413d80 in cnt_lookup (sp=0x2aaab3d00008) at
 cache_center.c:891
 #3  0x00000000004165f9 in CNT_Session (sp=0x2aaab3d00008) at steps.h:39
 #4  0x000000000041dcc7 in ved_include (sp=0x2aaab3d00008) at
 cache_esi_deliver.c:104
 #5  ESI_Deliver (sp=0x2aaab3d00008) at cache_esi_deliver.c:366
 #6  0x000000000042cf38 in RES_WriteObj (sp=0x2aaab3d00008) at
 cache_response.c:380
 #7  0x00000000004155e0 in cnt_deliver (sp=0x2aaab3d00008) at
 cache_center.c:241
 #8  0x0000000000416489 in CNT_Session (sp=0x2aaab3d00008) at steps.h:44
 #9  0x000000000042c8d8 in wrk_do_cnt_sess (w=0x52800de0, priv=<value
 optimized out>) at cache_pool.c:303
 #10 0x000000000042babf in wrk_thread_real (qp=0x2af972b0b100,
 shm_workspace=<value optimized out>, sess_workspace=65536,
     nhttp=64, http_space=<value optimized out>, siov=128) at
 cache_pool.c:187
 #11 0x0000003aac40673d in start_thread () from /lib64/libpthread.so.0
 #12 0x0000003aabcd3f6d in clone () from /lib64/libc.so.6
 (gdb) frame 0
 #0  ban_check_object (o=0x2aaab0099900, sp=0x2aaab3d00008, has_req=1) at
 cache_ban.c:448
 448                     if (b->flags & BAN_F_GONE)
 (gdb) display b
 (gdb) print b
 $1 = (struct ban *) 0x0
 (gdb) display b0
 (gdb) print b0
 $2 = (struct ban * volatile) 0x2aaab06e78e0
 (gdb) print *b0
 $3 = {magic = 1879771370, list = {vtqe_next = 0x2aaaafbf8820, vtqe_prev =
 0x66fdc0}, refcount = 3034, flags = 0, tests = {
     vtqh_first = 0x2aaaae150080, vtqh_last = 0x2aaaae150088}, objcore =
 {vtqh_first = 0x2aaab0a3b4a0,
     vtqh_last = 0x2aaab0068728}, t0 = 1301480974.880106, vsb = 0x0,
   test = 0x2aaaafbf70a0 "obj.http.cache-control ~ group=%22/sec25171%22"}
 (gdb) display *b0->list->vtqe_next
 (gdb) display *(b0->list->vtqe_next)
 (gdb) print *(b0->list->vtqe_next)
 $4 = {magic = 1879771370, list = {vtqe_next = 0x2aaab0a4f400, vtqe_prev =
 0x2aaab06e78e8}, refcount = 0, flags = 0, tests = {
     vtqh_first = 0x2aaaae150040, vtqh_last = 0x2aaaae150048}, objcore =
 {vtqh_first = 0x0, vtqh_last = 0x2aaaafbf8850},
   t0 = 1301480974.87623, vsb = 0x0, test = 0x2aaaafbf7070 "obj.http.cache-
 control ~ group=%22/sec171%22"}
 (gdb) print *(b0->list->vtqe_next->list->vtqe_next)
 $5 = {magic = 1879771370, list = {vtqe_next = 0x0, vtqe_prev =
 0x2aaaafbf8828}, refcount = 610, flags = 1, tests = {
     vtqh_first = 0x2aaaabd8b080, vtqh_last = 0x2aaaabd8b088}, objcore =
 {vtqh_first = 0x2aaab0068820,
     vtqh_last = 0x2aaaafa95028}, t0 = 1301480969.8811419, vsb = 0x0,
   test = 0x2aaab0a33070 "obj.http.cache-control ~ group=%22/sec25171%22"}
 (gdb) print oc->ban
 $6 = (struct ban *) 0x2aaab06e78e0
 (gdb) print *oc->ban
 $7 = {magic = 1879771370, list = {vtqe_next = 0x2aaaafbf8820, vtqe_prev =
 0x66fdc0}, refcount = 3034, flags = 0, tests = {
     vtqh_first = 0x2aaaae150080, vtqh_last = 0x2aaaae150088}, objcore =
 {vtqh_first = 0x2aaab0a3b4a0,
     vtqh_last = 0x2aaab0068728}, t0 = 1301480974.880106, vsb = 0x0,
   test = 0x2aaaafbf70a0 "obj.http.cache-control ~ group=%22/sec25171%22"}
 (gdb) print *oc
 $8 = {magic = 1294996226, refcnt = 2, methods = 0x671400, priv =
 0x2aaab0099900, priv2 = 0, objhead = 0x2aaab00687b0,
   timer_when = 1301595397.7503209, flags = 0, timer_idx = 2661, list =
 {vtqe_next = 0x0, vtqe_prev = 0x2aaab00687c8},
   lru_list = {vtqe_next = 0x2aaab0068820, vtqe_prev = 0x2aaaafac7408},
 ban_list = {vtqe_next = 0x0,
     vtqe_prev = 0x2aaab0068648}, ban = 0x2aaab06e78e0}
 (gdb) bt
 #0  ban_check_object (o=0x2aaab0099900, sp=0x2aaab3d00008, has_req=1) at
 cache_ban.c:448
 #1  0x000000000042449c in HSH_Lookup (sp=0x2aaab3d00008, poh=0x527e5578)
 at cache_hash.c:359
 #2  0x0000000000413d80 in cnt_lookup (sp=0x2aaab3d00008) at
 cache_center.c:891
 #3  0x00000000004165f9 in CNT_Session (sp=0x2aaab3d00008) at steps.h:39
 #4  0x000000000041dcc7 in ved_include (sp=0x2aaab3d00008) at
 cache_esi_deliver.c:104
 #5  ESI_Deliver (sp=0x2aaab3d00008) at cache_esi_deliver.c:366
 #6  0x000000000042cf38 in RES_WriteObj (sp=0x2aaab3d00008) at
 cache_response.c:380
 #7  0x00000000004155e0 in cnt_deliver (sp=0x2aaab3d00008) at
 cache_center.c:241
 #8  0x0000000000416489 in CNT_Session (sp=0x2aaab3d00008) at steps.h:44
 #9  0x000000000042c8d8 in wrk_do_cnt_sess (w=0x52800de0, priv=<value
 optimized out>) at cache_pool.c:303
 #10 0x000000000042babf in wrk_thread_real (qp=0x2af972b0b100,
 shm_workspace=<value optimized out>, sess_workspace=65536,
     nhttp=64, http_space=<value optimized out>, siov=128) at
 cache_pool.c:187
 #11 0x0000003aac40673d in start_thread () from /lib64/libpthread.so.0
 #12 0x0000003aabcd3f6d in clone () from /lib64/libc.so.6
 (gdb) quit
 }}}

 Note that this essentially boils down to oc->ban == b0, even after the
 test a few lines above.

 The server is running varnishd (varnish-trunk revision e01527c) and is
 seeing frequent bans. There's no live-traffic, but I trigger this fairly
 easily with a wget -p over a front page (In a manner of minutes).

 I'm about to test without the ban lurker to see if that's the only way to
 trigger it.

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