[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