[Varnish] #1542: Child (21196) Panic message:#012Assert error in Lck__Lock(), cache/cache_lck.c line 70

Varnish varnish-bugs at varnish-cache.org
Mon Jul 7 12:06:53 CEST 2014


#1542: Child (21196) Panic message:#012Assert error in Lck__Lock(),
cache/cache_lck.c line 70
-----------------------+----------------------------------
 Reporter:  cmartinez  |       Owner:
     Type:  defect     |      Status:  new
 Priority:  normal     |   Milestone:  Varnish 4.0 release
Component:  varnishd   |     Version:  4.0.1
 Severity:  critical   |  Resolution:
 Keywords:             |
-----------------------+----------------------------------
Description changed by lkarsten:

Old description:

> we upgraded varnish from 4.0.0 to try to fix this issue but is still
> reproducing
>
> Varnish restarts his childs with signal 11.
>
> debug info:
>

> varnish> panic.show
> 200
> Last panic at: Wed, 02 Jul 2014 08:19:22 GMT
> Assert error in Lck__Lock(), cache/cache_lck.c line 71:
>   Condition((pthread_mutex_lock(&ilck->mtx)) == 0) not true.
> thread = (cache-worker)
> ident =
> Linux,2.6.32-431.el6.x86_64,x86_64,-smalloc,-smalloc,-hcritbit,epoll
> Backtrace:
>   0x43b0bd: /usr/sbin/varnishd() [0x43b0bd]
>   0x43b3cd: /usr/sbin/varnishd() [0x43b3cd]
>   0x436aba: /usr/sbin/varnishd(Lck__Lock+0xd2) [0x436aba]
>   0x4184e0: /usr/sbin/varnishd(VBO_waitlen+0x30) [0x4184e0]
>   0x4436aa: /usr/sbin/varnishd() [0x4436aa]
>   0x4442ae: /usr/sbin/varnishd(V1D_Deliver+0x597) [0x4442ae]
>   0x43f697: /usr/sbin/varnishd() [0x43f697]
>   0x4429f5: /usr/sbin/varnishd(CNT_Request+0x529) [0x4429f5]
>   0x433a40: /usr/sbin/varnishd(HTTP1_Session+0x429) [0x433a40]
>   0x44594b: /usr/sbin/varnishd() [0x44594b]
> req = 0x7f6e3e2bc020 {
>   sp = 0x7f6ff981b8e0, vxid = 1084098135,  step = R_STP_DELIVER,
>   req_body = R_BODY_NONE,
>   err_code = 200, err_reason = (null),
>   restarts = 0, esi_level = 0
>   sp = 0x7f6ff981b8e0 {
>     fd = 40, vxid = 10356310,
>     client = 10.13.3.40 41544,
>     step = S_STP_WORKING,
>   },
>   worker = 0x7f6e55b4abf0 {
>     ws = 0x7f6e55b4ae08 {
>       id = "wrk",
>       {s,f,r,e} = {0x7f6e55b4a3d0,0x7f6e55b4a3d0,(nil),+2048},
>     },
>   VCL::method = 0x0,
>   VCL::return = deliver,
>   },
>   ws = 0x7f6e3e2bc1b8 {
>     id = "req",
>     {s,f,r,e} = {0x7f6e3e2be010,+416,(nil),+57360},
>   },
>
> (gdb) bt
> #0  0x00000000004184eb in VBO_waitlen ()
> #1  0x00000000004436aa in v1d_dorange ()
> #2  0x00000000004442ae in V1D_Deliver ()
> #3  0x000000000043f697 in cnt_deliver ()
> #4  0x00000000004429f5 in CNT_Request ()
> #5  0x0000000000433a40 in HTTP1_Session ()
> #6  0x000000000044594b in ses_req_pool_task ()
> #7  0x0000000000445c16 in ses_sess_pool_task ()
> #8  0x00000000004461c2 in SES_pool_accept_task ()
> #9  0x000000000043e035 in Pool_Work_Thread ()
> #10 0x0000000000456218 in wrk_thread_real ()
> #11 0x0000000000456341 in WRK_thread ()
> #12 0x000000352ba079d1 in start_thread (arg=0x7f6ef489d700) at
> pthread_create.c:301
> #13 0x000000352b6e8b6d in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
> (gdb) frame 12
> #12 0x000000352ba079d1 in start_thread (arg=0x7f6ef489d700) at
> pthread_create.c:301
> 301           THREAD_SETMEM (pd, result, CALL_THREAD_FCT (pd));
> (gdb) print pd
> $1 = (struct pthread *) 0x7f6ef489d700
> (gdb) print *pd
> $2 = {{header = {tcb = 0x7f6ef489d700, dtv = 0x7f6f76c11850, self =
> 0x7f6ef489d700, multiple_threads = 1, gscope_flag = 0,
>       sysinfo = 0, stack_guard = 5883901357024911704, pointer_guard =
> 13223282705651353577, vgetcpu_cache = {0, 0},
>       private_futex = 128, rtld_must_xmm_save = 0, __private_tm = {0x0,
> 0x0, 0x0, 0x0, 0x0}, __unused2 = 0, rtld_savespace_sse = {{{
>             0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0,
> 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0,
>             0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0,
> 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0,
>             0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0, 0,
> 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0, 0,
>             0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0, 0, 0},
> {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}}, __padding = {
>         0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}}, __padding =
> {0x7f6ef489d700, 0x7f6f76c11850, 0x7f6ef489d700, 0x1, 0x0,
>       0x51a7d11c26e8a158, 0xb782898f92ea47e9, 0x0, 0x0, 0x80, 0x0
> <repeats 14 times>}}, list = {next = 0x7f6ef48a99c0,
>     prev = 0x7f6ef48919c0}, tid = 21040, pid = 20618, robust_prev =
> 0x7f6ef489d9e0, robust_head = {list = 0x7f6ef489d9e0,
>     futex_offset = -32, list_op_pending = 0x0}, cleanup = 0x0,
> cleanup_jmp_buf = 0x7f6ef489cf30, cancelhandling = 0, flags = 0,
>   specific_1stblock = {{seq = 1, data = 0x7f6ef489d6d0}, {seq = 1, data =
> 0x7f6ef489d6f8}, {seq = 0, data = 0x0}, {seq = 1,
>       data = 0x7f6e5a352020}, {seq = 1, data = 0x0}, {seq = 1, data =
> 0x48354a}, {seq = 0, data = 0x0} <repeats 26 times>},
>   specific = {0x7f6ef489da10, 0x0 <repeats 31 times>}, specific_used =
> true, report_events = false, user_stack = false,
>   stopped_start = false, parent_cancelhandling = 0, lock = 0,
> setxid_futex = 0, cpuclock_offset = 7204934909057508,
>   joinid = 0x7f6ef489d700, result = 0x0, schedparam = {__sched_priority =
> 0}, schedpolicy = 0,
>   start_routine = 0x45631a <WRK_thread>, arg = 0x7f70a0c0e300, eventbuf =
> {eventmask = {event_bits = {0, 0}},
>     eventnum = TD_ALL_EVENTS, eventdata = 0x0}, nextevent = 0x0, exc =
> {exception_class = 0, exception_cleanup = 0, private_1 = 0,
>     private_2 = 0}, stackblock = 0x7f6ef4892000, stackblock_size = 49152,
> guardsize = 4096, reported_guardsize = 4096, tpp = 0x0,
>   res = {retrans = 0, retry = 0, options = 0, nscount = 0, nsaddr_list =
> {{sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0},
>         sin_zero = "\000\000\000\000\000\000\000"}, {sin_family = 0,
> sin_port = 0, sin_addr = {s_addr = 0},
>         sin_zero = "\000\000\000\000\000\000\000"}, {sin_family = 0,
> sin_port = 0, sin_addr = {s_addr = 0},
>         sin_zero = "\000\000\000\000\000\000\000"}}, id = 0, dnsrch =
> {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0},
>     defdname = '\000' <repeats 255 times>, pfcode = 0, ndots = 0, nsort =
> 0, ipv6_unavail = 0, unused = 0, sort_list = {{addr = {
>           s_addr = 0}, mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr
> = {s_addr = 0}, mask = 0}, {addr = {s_addr = 0},
>         mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr = {s_addr = 0},
> mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr = {
>           s_addr = 0}, mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr
> = {s_addr = 0}, mask = 0}}, qhook = 0, rhook = 0,
>     res_h_errno = 0, _vcsock = 0, _flags = 0, _u = {pad = '\000' <repeats
> 51 times>, _ext = {nscount = 0, nsmap = {0, 0, 0},
>         nssocks = {0, 0, 0}, nscount6 = 0, nsinit = 0, nsaddrs = {0x0,
> 0x0, 0x0}, initstamp = 0}}}, end_padding = 0x7f6ef489d700 ""}
>
> (gdb) print result
> $3 = '\000' <repeats 113 times>

New description:

 we upgraded varnish from 4.0.0 to try to fix this issue but is still
 reproducing

 Varnish restarts his childs with signal 11.

 debug info:

 {{{
 varnish> panic.show
 200
 Last panic at: Wed, 02 Jul 2014 08:19:22 GMT
 Assert error in Lck__Lock(), cache/cache_lck.c line 71:
   Condition((pthread_mutex_lock(&ilck->mtx)) == 0) not true.
 thread = (cache-worker)
 ident =
 Linux,2.6.32-431.el6.x86_64,x86_64,-smalloc,-smalloc,-hcritbit,epoll
 Backtrace:
   0x43b0bd: /usr/sbin/varnishd() [0x43b0bd]
   0x43b3cd: /usr/sbin/varnishd() [0x43b3cd]
   0x436aba: /usr/sbin/varnishd(Lck__Lock+0xd2) [0x436aba]
   0x4184e0: /usr/sbin/varnishd(VBO_waitlen+0x30) [0x4184e0]
   0x4436aa: /usr/sbin/varnishd() [0x4436aa]
   0x4442ae: /usr/sbin/varnishd(V1D_Deliver+0x597) [0x4442ae]
   0x43f697: /usr/sbin/varnishd() [0x43f697]
   0x4429f5: /usr/sbin/varnishd(CNT_Request+0x529) [0x4429f5]
   0x433a40: /usr/sbin/varnishd(HTTP1_Session+0x429) [0x433a40]
   0x44594b: /usr/sbin/varnishd() [0x44594b]
 req = 0x7f6e3e2bc020 {
   sp = 0x7f6ff981b8e0, vxid = 1084098135,  step = R_STP_DELIVER,
   req_body = R_BODY_NONE,
   err_code = 200, err_reason = (null),
   restarts = 0, esi_level = 0
   sp = 0x7f6ff981b8e0 {
     fd = 40, vxid = 10356310,
     client = 10.13.3.40 41544,
     step = S_STP_WORKING,
   },
   worker = 0x7f6e55b4abf0 {
     ws = 0x7f6e55b4ae08 {
       id = "wrk",
       {s,f,r,e} = {0x7f6e55b4a3d0,0x7f6e55b4a3d0,(nil),+2048},
     },
   VCL::method = 0x0,
   VCL::return = deliver,
   },
   ws = 0x7f6e3e2bc1b8 {
     id = "req",
     {s,f,r,e} = {0x7f6e3e2be010,+416,(nil),+57360},
   },
 }}}

 {{{
 (gdb) bt
 #0  0x00000000004184eb in VBO_waitlen ()
 #1  0x00000000004436aa in v1d_dorange ()
 #2  0x00000000004442ae in V1D_Deliver ()
 #3  0x000000000043f697 in cnt_deliver ()
 #4  0x00000000004429f5 in CNT_Request ()
 #5  0x0000000000433a40 in HTTP1_Session ()
 #6  0x000000000044594b in ses_req_pool_task ()
 #7  0x0000000000445c16 in ses_sess_pool_task ()
 #8  0x00000000004461c2 in SES_pool_accept_task ()
 #9  0x000000000043e035 in Pool_Work_Thread ()
 #10 0x0000000000456218 in wrk_thread_real ()
 #11 0x0000000000456341 in WRK_thread ()
 #12 0x000000352ba079d1 in start_thread (arg=0x7f6ef489d700) at
 pthread_create.c:301
 #13 0x000000352b6e8b6d in clone () at
 ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
 (gdb) frame 12
 #12 0x000000352ba079d1 in start_thread (arg=0x7f6ef489d700) at
 pthread_create.c:301
 301           THREAD_SETMEM (pd, result, CALL_THREAD_FCT (pd));
 (gdb) print pd
 $1 = (struct pthread *) 0x7f6ef489d700
 (gdb) print *pd
 $2 = {{header = {tcb = 0x7f6ef489d700, dtv = 0x7f6f76c11850, self =
 0x7f6ef489d700, multiple_threads = 1, gscope_flag = 0,
       sysinfo = 0, stack_guard = 5883901357024911704, pointer_guard =
 13223282705651353577, vgetcpu_cache = {0, 0},
       private_futex = 128, rtld_must_xmm_save = 0, __private_tm = {0x0,
 0x0, 0x0, 0x0, 0x0}, __unused2 = 0, rtld_savespace_sse = {{{
             0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0,
 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0,
             0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0,
 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0,
             0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0, 0,
 0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0, 0,
             0}, {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}, {{0, 0, 0, 0},
 {0, 0, 0, 0}, {0, 0, 0, 0}, {0, 0, 0, 0}}}, __padding = {
         0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}}, __padding =
 {0x7f6ef489d700, 0x7f6f76c11850, 0x7f6ef489d700, 0x1, 0x0,
       0x51a7d11c26e8a158, 0xb782898f92ea47e9, 0x0, 0x0, 0x80, 0x0 <repeats
 14 times>}}, list = {next = 0x7f6ef48a99c0,
     prev = 0x7f6ef48919c0}, tid = 21040, pid = 20618, robust_prev =
 0x7f6ef489d9e0, robust_head = {list = 0x7f6ef489d9e0,
     futex_offset = -32, list_op_pending = 0x0}, cleanup = 0x0,
 cleanup_jmp_buf = 0x7f6ef489cf30, cancelhandling = 0, flags = 0,
   specific_1stblock = {{seq = 1, data = 0x7f6ef489d6d0}, {seq = 1, data =
 0x7f6ef489d6f8}, {seq = 0, data = 0x0}, {seq = 1,
       data = 0x7f6e5a352020}, {seq = 1, data = 0x0}, {seq = 1, data =
 0x48354a}, {seq = 0, data = 0x0} <repeats 26 times>},
   specific = {0x7f6ef489da10, 0x0 <repeats 31 times>}, specific_used =
 true, report_events = false, user_stack = false,
   stopped_start = false, parent_cancelhandling = 0, lock = 0, setxid_futex
 = 0, cpuclock_offset = 7204934909057508,
   joinid = 0x7f6ef489d700, result = 0x0, schedparam = {__sched_priority =
 0}, schedpolicy = 0,
   start_routine = 0x45631a <WRK_thread>, arg = 0x7f70a0c0e300, eventbuf =
 {eventmask = {event_bits = {0, 0}},
     eventnum = TD_ALL_EVENTS, eventdata = 0x0}, nextevent = 0x0, exc =
 {exception_class = 0, exception_cleanup = 0, private_1 = 0,
     private_2 = 0}, stackblock = 0x7f6ef4892000, stackblock_size = 49152,
 guardsize = 4096, reported_guardsize = 4096, tpp = 0x0,
   res = {retrans = 0, retry = 0, options = 0, nscount = 0, nsaddr_list =
 {{sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0},
         sin_zero = "\000\000\000\000\000\000\000"}, {sin_family = 0,
 sin_port = 0, sin_addr = {s_addr = 0},
         sin_zero = "\000\000\000\000\000\000\000"}, {sin_family = 0,
 sin_port = 0, sin_addr = {s_addr = 0},
         sin_zero = "\000\000\000\000\000\000\000"}}, id = 0, dnsrch =
 {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0},
     defdname = '\000' <repeats 255 times>, pfcode = 0, ndots = 0, nsort =
 0, ipv6_unavail = 0, unused = 0, sort_list = {{addr = {
           s_addr = 0}, mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr =
 {s_addr = 0}, mask = 0}, {addr = {s_addr = 0},
         mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr = {s_addr = 0},
 mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr = {
           s_addr = 0}, mask = 0}, {addr = {s_addr = 0}, mask = 0}, {addr =
 {s_addr = 0}, mask = 0}}, qhook = 0, rhook = 0,
     res_h_errno = 0, _vcsock = 0, _flags = 0, _u = {pad = '\000' <repeats
 51 times>, _ext = {nscount = 0, nsmap = {0, 0, 0},
         nssocks = {0, 0, 0}, nscount6 = 0, nsinit = 0, nsaddrs = {0x0,
 0x0, 0x0}, initstamp = 0}}}, end_padding = 0x7f6ef489d700 ""}

 (gdb) print result
 $3 = '\000' <repeats 113 times>
 }}}

--

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



More information about the varnish-bugs mailing list