Re: (ITS#6798) Mutex starvation on two-level referral for SASL connection - openldap-bugs

20 Jan 2011


      Hi
Here's some information that Stephen asked would be of use. There is 
one forest, one domain, but three sites in the layout. The functional 
level of the forest and the domain is W2008, but the servers have 2008R2.
And the full backtrace of the hung process:
#0  __lll_lock_wait () at 
../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
No locals.
#1  0x00007f8f63ec05d9 in _L_lock_953 () from /lib/libpthread.so.0
No symbol table info available.
#2  0x00007f8f63ec03fb in __pthread_mutex_lock (mutex=0x7f8f6553fc80)
     at pthread_mutex_lock.c:61
         ignore1 = <value optimized out>
         ignore2 = 1700002944
         ignore3 = -512
         __PRETTY_FUNCTION__ = "__pthread_mutex_lock"
         type = <value optimized out>
#3  0x00007f8f652f3bcb in ldap_pvt_thread_mutex_lock 
(mutex=0x7f8f6553fc80)
     at /tmp/buildd/openldap-2.4.23/libraries/libldap_r/thr_posix.c:296
No locals.
#4  0x00007f8f653010bf in ldap_sasl_interactive_bind_s (ld=0x2117c20, 
dn=0x0,
     mechs=0x210d530 "GSSAPI", serverControls=0x0, clientControls=0x0, 
flags=2,
     interact=0x7f8f61405120 <sdap_sasl_interact>, defaults=0x2124a50) at 
sasl.c:426
         rc = -1921681294
         smechs = 0x0
#5  0x00007f8f6140888d in sdap_rebind_proc (ldap=0x2117c20,
     url=0x2125a00 
"ldap://DomainDnsZones.domain.com/DC=DomainDnsZones,DC=domain,DC=com", 
request=<value optimized out>, msgid=<value optimized out>, params=<value 
optimized out>)
     at src/providers/ldap/sdap_async_connection.c:1637
         p = <value optimized out>
         sasl_mech = <value optimized out>
         user_dn = <value optimized out>
         password = {bv_len = 0, bv_val = 0x0}
         ctrls = {0x0, 0x0}
         tmp_ctx = <value optimized out>
         ret = <value optimized out>
         __FUNCTION__ = "sdap_rebind_proc"
#6  0x00007f8f65310a46 in ldap_new_connection (ld=0x2117c20, 
srvlist=0x7fffdebf22f8,
     use_ldsb=0, connect=1, bind=0x7fffdebf22b0) at request.c:518
         srvfunc = 0x2122da0
         err = 0
         savedefconn = 0x21208d0
         lc = 0x21227c0
         async = 0
         __PRETTY_FUNCTION__ = "ldap_new_connection"
#7  0x00007f8f6530fdf0 in ldap_send_server_request (ld=0x2117c20, 
ber=0x2122760, msgid=8,
     parentreq=0x21304f0, srvlist=0x7fffdebf22f8, lc=0x0, 
bind=0x7fffdebf22b0) at request.c:211
         lr = 0x63
         incparent = 1
         rc = 1697594315
#8  0x00007f8f653125dc in ldap_chase_v3referrals (ld=0x2117c20, 
lr=0x21304f0, refs=0x0,
     sref=1, errstrp=0x2130520, hadrefp=0x7fffdebf24f8) at request.c:1211
         unfollowed = 0x0
         unfollowedcnt = 0
         origreq = 0x21304f0
         srv = 0x2125a60
         ber = 0x2122760
         refarray = 0x2122720
         lc = 0x0
         rc = 0
         count = 0
         i = 0
         j = 0
         id = 8
         rinfo = {ri_msgid = 5, ri_request = 99,
           ri_url = 0x2125a00 
"ldap://DomainDnsZones.domain.com/DC=DomainDnsZones,DC=domain,DC=com"}
#9  0x00007f8f652f6165 in try_read1msg (ld=0x2117c20, msgid=7, all=1, 
lc=0x2117760,
     result=0x7fffdebf26b0) at result.c:708
         refs = 0x2122720
         ber = 0x212e910
         newmsg = 0x2117c20
         l = 0x2124140
         prev = 0x7debf25e0
         id = 5
         idx = 0
         tag = 115
         len = 76
         foundit = 0
         lr = 0x21304f0
         tmplr = 0x7f8f6531039d
         dummy_lr = {lr_msgid = 0, lr_status = 0, lr_refcnt = 0, 
lr_outrefcnt = 0,
           lr_abandoned = 0, lr_origid = 0, lr_parentcnt = 0, 
lr_res_msgtype = 0,
           lr_res_errno = 0, lr_res_error = 0x0, lr_res_matched = 0x0, 
lr_ber = 0x0,
           lr_conn = 0x0, lr_dn = {bv_len = 0, bv_val = 0x0}, lr_parent = 
0x0, lr_child = 0x0,
           lr_refnext = 0x0, lr_prev = 0x0, lr_next = 0x0}
         tmpber = {ber_opts = {lbo_valid = 2, lbo_options = 1, lbo_debug = 
0}, ber_tag = 0,
           ber_len = 85, ber_usertag = 0, ber_buf = 0x2131cd0 
"\002\001\005s\204",
           ber_ptr = 0x2131d25 "", ber_end = 0x2131d25 "", ber_sos_ptr = 
0x0, ber_rwptr = 0x0,
           ber_memctx = 0x0}
         rc = -2
         refer_cnt = 0
         hadref = 0
         simple_request = 0
         err = 1
         lderr = 0
         tmp = 0x0
         chain_head = 0x0
         moremsgs = 0
         isv2 = 0
         __PRETTY_FUNCTION__ = "try_read1msg"
#10 0x00007f8f652f571b in wait4msg (ld=0x2117c20, msgid=7, all=1, 
timeout=0x7fffdebf25b0,
     result=0x7fffdebf26b0) at result.c:390
         lnext = 0x2117760
         lc_ready = 1
         rc = -2
         tv = {tv_sec = 6, tv_usec = 0}
         tv0 = {tv_sec = 6, tv_usec = 0}
         start_time_tv = {tv_sec = 1295533580, tv_usec = 63738}
         tvp = 0x7fffdebf25b0
         lc = 0x2117760
         __PRETTY_FUNCTION__ = "wait4msg"
#11 0x00007f8f652f4ddf in ldap_result (ld=0x2117c20, msgid=7, all=1, 
timeout=0x0,
     result=0x7fffdebf26b0) at result.c:120
         rc = 1227
         __PRETTY_FUNCTION__ = "ldap_result"
#12 0x00007f8f65300a06 in ldap_sasl_bind_s (ld=0x2117c20, dn=0x0,
     mechanism=0x7f8f5ffe894c "GSSAPI", cred=0x7fffdebf2740, sctrls=0x0, 
cctrls=0x0,
     servercredp=0x7fffdebf2758) at sasl.c:194
         rc = 0
         msgid = 7
         result = 0x0
         scredp = 0x0
#13 0x00007f8f652fce5b in ldap_int_sasl_bind (ld=0x2117c20, dn=0x0, 
mechs=0x210d530 "GSSAPI",
     sctrls=0x0, cctrls=0x0, flags=2, interact=0x7f8f61405120 
<sdap_sasl_interact>,
     defaults=0x21170b0) at cyrus.c:535
         scred = 0x0
         credlen = 32767
         data = 0x8d757872de362e00 <Address 0x8d757872de362e00 out of 
bounds>
         mech = 0x7f8f5ffe894c "GSSAPI"
         pmech = 0x7f8f5ffe894c "GSSAPI"
         saslrc = 1
         rc = 0
         ssf = 0x0
         ctx = 0x2127380
         oldctx = 0x0
         prompts = 0x0
         credlen = 1202
         ccred = {bv_len = 1202,
           bv_val = 0x2125540 
"`\202\004\256\006\t*\206H\206\367\022\001\002\002\001"}
         sd = 23
         ssl = 0x0
#14 0x00007f8f6530120f in ldap_sasl_interactive_bind_s (ld=0x2117c20, 
dn=0x0,
     mechs=0x210d530 "GSSAPI", serverControls=0x0, clientControls=0x0, 
flags=2,
     interact=0x7f8f61405120 <sdap_sasl_interact>, defaults=0x21170b0) at 
sasl.c:464
         rc = -1921681294
         smechs = 0x0
#15 0x00007f8f6140888d in sdap_rebind_proc (ldap=0x2117c20,
     url=0x2126270 
"ldap://ForestDnsZones.domain.com/DC=ForestDnsZones,DC=domain,DC=com", 
request=<value optimized out>, msgid=<value optimized out>, params=<value 
optimized out>)
     at src/providers/ldap/sdap_async_connection.c:1637
         p = <value optimized out>
         sasl_mech = <value optimized out>
         user_dn = <value optimized out>
         password = {bv_len = 0, bv_val = 0x0}
         ctrls = {0x0, 0x0}
         tmp_ctx = <value optimized out>
         ret = <value optimized out>
         __FUNCTION__ = "sdap_rebind_proc"
#16 0x00007f8f65310a46 in ldap_new_connection (ld=0x2117c20, 
srvlist=0x7fffdebf2bd8,
     use_ldsb=0, connect=1, bind=0x7fffdebf2b90) at request.c:518
         srvfunc = 0x2122190
         err = 0
         savedefconn = 0x2117760
         lc = 0x21208d0
         async = 0
         __PRETTY_FUNCTION__ = "ldap_new_connection"
#17 0x00007f8f6530fdf0 in ldap_send_server_request (ld=0x2117c20, 
ber=0x21206e0, msgid=6,
     parentreq=0x21304f0, srvlist=0x7fffdebf2bd8, lc=0x0, 
bind=0x7fffdebf2b90) at request.c:211
         lr = 0x63
         incparent = 1
         rc = 1697594315
#18 0x00007f8f653125dc in ldap_chase_v3referrals (ld=0x2117c20, 
lr=0x21304f0, refs=0x0,
     sref=1, errstrp=0x2130520, hadrefp=0x7fffdebf2dd8) at request.c:1211
         unfollowed = 0x0
         unfollowedcnt = 0
         origreq = 0x21304f0
         srv = 0x2116b40
         ber = 0x21206e0
         refarray = 0x212b470
         lc = 0x0
         rc = 0
         count = 0
         i = 0
         j = 0
         id = 6
         rinfo = {ri_msgid = 5, ri_request = 99,
           ri_url = 0x2126270 
"ldap://ForestDnsZones.domain.com/DC=ForestDnsZones,DC=domain,DC=com"}
#19 0x00007f8f652f6165 in try_read1msg (ld=0x2117c20, msgid=-1, all=0, 
lc=0x2117760,
     result=0x7fffdebf2f68) at result.c:708
         refs = 0x212b470
         ber = 0x2122580
         newmsg = 0x7f8f674287b8
         l = 0x7fffdebf2ef0
         prev = 0x7f8f67460cd8
         id = 5
         idx = 0
         tag = 115
         len = 76
         foundit = 0
         lr = 0x21304f0
         tmplr = 0x100000000
         dummy_lr = {lr_msgid = 0, lr_status = 0, lr_refcnt = 0, 
lr_outrefcnt = 0,
           lr_abandoned = 0, lr_origid = 0, lr_parentcnt = 0, 
lr_res_msgtype = 0,
           lr_res_errno = 0, lr_res_error = 0x0, lr_res_matched = 0x0, 
lr_ber = 0x0,
           lr_conn = 0x0, lr_dn = {bv_len = 0, bv_val = 0x0}, lr_parent = 
0x0, lr_child = 0x0,
           lr_refnext = 0x0, lr_prev = 0x0, lr_next = 0x0}
         tmpber = {ber_opts = {lbo_valid = 2, lbo_options = 1, lbo_debug = 
0}, ber_tag = 0,
           ber_len = 85, ber_usertag = 0, ber_buf = 0x2125410 
"\002\001\005s\204",
           ber_ptr = 0x2125465 "", ber_end = 0x2125465 "", ber_sos_ptr = 
0x0, ber_rwptr = 0x0,
           ber_memctx = 0x0}
         rc = -2
         refer_cnt = 0
         hadref = 0
         simple_request = 0
         err = 0
         lderr = 32655
         tmp = 0x0
         chain_head = 0x0
         moremsgs = 0
         isv2 = 0
         __PRETTY_FUNCTION__ = "try_read1msg"
#20 0x00007f8f652f571b in wait4msg (ld=0x2117c20, msgid=-1, all=0, 
timeout=0x7fffdebf2f50,
     result=0x7fffdebf2f68) at result.c:390
         lnext = 0x7f8f6742f000
         lc_ready = 1
         rc = -2
         tv = {tv_sec = 0, tv_usec = 0}
         tv0 = {tv_sec = 0, tv_usec = 0}
         start_time_tv = {tv_sec = 1295533580, tv_usec = 60251}
         tvp = 0x7fffdebf2e90
         lc = 0x2117760
         __PRETTY_FUNCTION__ = "wait4msg"
#21 0x00007f8f652f4ddf in ldap_result (ld=0x2117c20, msgid=-1, all=0, 
timeout=0x7fffdebf2f50,
     result=0x7fffdebf2f68) at result.c:120
         rc = 32655
         __PRETTY_FUNCTION__ = "ldap_result"
#22 0x00007f8f613f7cb4 in sdap_process_result (ev=0x20f11f0, pvt=<value 
optimized out>)
     at src/providers/ldap/sdap_async.c:178
         sh = 0x21176f0
         no_timeout = {tv_sec = 0, tv_usec = 0}
         te = <value optimized out>
         msg = <value optimized out>
         ret = <value optimized out>
         __FUNCTION__ = "sdap_process_result"
#23 0x00007f8f66e3077e in ?? () from /usr/lib/libtevent.so.0
No symbol table info available.
#24 0x00007f8f66e2d9f0 in _tevent_loop_once () from 
/usr/lib/libtevent.so.0
No symbol table info available.
#25 0x00007f8f66e2da5b in ?? () from /usr/lib/libtevent.so.0
No symbol table info available.
#26 0x0000000000431e51 in server_loop (main_ctx=0x20f2360) at 
src/util/server.c:526
No locals.
#27 0x000000000040f8bb in main (argc=5, argv=<value optimized out>)
     at src/providers/data_provider_be.c:1333
         opt = <value optimized out>
         pc = <value optimized out>
         be_domain = 0x20e8490 "DOMAIN"
         srv_name = <value optimized out>
         conf_entry = <value optimized out>
         main_ctx = 0x20f2360
         ret = 0
         long_options = {{longName = 0x0, shortName = 0 '\000', argInfo = 
4, arg = 0x644d00,
             val = 0, descrip = 0x436e64 "Help options:", argDescrip = 
0x0}, {
             longName = 0x436e72 "debug-level", shortName = 100 'd', 
argInfo = 2,
             arg = 0x644de0, val = 0, descrip = 0x436e43 "Debug level", 
argDescrip = 0x0}, {
             longName = 0x436e7e "debug-to-files", shortName = 102 'f', 
argInfo = 0,
             arg = 0x644de4, val = 0,
             descrip = 0x437ad8 "Send the debug output to files instead of 
stderr",
             argDescrip = 0x0}, {longName = 0x436e8d "debug-timestamps", 
shortName = 0 '\000',
             argInfo = 2, arg = 0x644cc0, val = 0, descrip = 0x436e4f "Add 
debug timestamps",
             argDescrip = 0x0}, {longName = 0x438458 "domain", shortName = 
0 '\000',
             argInfo = 1, arg = 0x7fffdebf31d8, val = 0,
             descrip = 0x437b10 "Domain of the information provider 
(mandatory)",
             argDescrip = 0x0}, {longName = 0x0, shortName = 0 '\000', 
argInfo = 0, arg = 0x0,
             val = 0, descrip = 0x0, argDescrip = 0x0}}
         __FUNCTION__ = "main"
-- 
Timo Aaltonen
Systems Specialist, Aalto IT