Issue 8433 - slapd deadlocks on shutdown in 3+ MMR configuration with active writes
Summary: slapd deadlocks on shutdown in 3+ MMR configuration with active writes
Status: VERIFIED SUSPENDED
Alias: None
Product: OpenLDAP
Classification: Unclassified
Component: slapd (show other issues)
Version: 2.4.44
Hardware: All All
: --- normal
Target Milestone: ---
Assignee: OpenLDAP project
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-06-03 23:18 UTC by Quanah Gibson-Mount
Modified: 2020-03-22 22:56 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this issue.
Description Quanah Gibson-Mount 2016-06-03 23:18:53 UTC
Full_Name: Quanah Gibson-Mount
Version: 2.4.44
OS: Linux 2.6
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (75.111.52.177)


Due to ITS#8432 causing there to be endless write activity on all MMR nodes,
slapd deadlocks on shutdown:

Jun  3 22:55:16 ldap02e zimbramon[8434]: 8434:info: Stopping antispam via
zmcontrol
Jun  3 22:55:17 ldap02e slapd[16804]: slap_queue_csn: queueing 0x57eb440
20160603194926.427963Z#000000#001#000000
Jun  3 22:55:17 ldap02e slapd[16804]: slap_graduate_commit_csn: removing
0x57eb440 20160603194926.427963Z#000000#001#000000
Jun  3 22:55: 7 ldap02e slapd[16804]: slap_graduate_commit_csn: removing
0xcbdc480 20160603194926.427963Z#000000#001#000000
Jun  3 22:55:17 ldap02e slapd[16804]: syncrepl_message_to_op: rid=100 be_modify
cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0)
Jun  3 22:55:17 ldap02e slapd[16804]: do_syncrep2: rid=100
cookie=rid=100,sid=003
Jun  3 22:55:17 ldap02e slapd[16804]: slap_queue_csn: queueing 0xcbdc480
20160603194926.427963Z#000000#001#000000
Jun  3 22:55:19 ldap02e slapd[16804]: slap_queue_csn: queueing 0xcbdc700
20160603194926.427963Z#000000#001#000000
Jun  3 22:55:19 ldap02e slapd[16804]: slap_graduate_commit_csn: removing
0xcbdc700 20160603194926.427963Z#000000#001#000000
Jun  3 22:55:19 ldap02e slapd[16804]: slap_graduate_commit_csn: removing
0xcbdc480 20160603194926.427963Z#000000#001#000000
Jun  3 22:55:19 ldap02e slapd[16804]: syncrepl_message_to_op: rid=100 be_modify
cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0)
Jun  3 22:55:19 ldap02e slapd[16804]: do_syncrep2: rid=100
cookie=rid=100,sid=003
Jun  3 22:55:19 ldap02e slapd[16804SA3A slap_queue_csn: queueing 0xcbdc480
20160603194926.427963Z#000000#001#000000
Jun  3 22:55:19 ldap02e slapd[16804]: conn=1072 fd=20 ACCEPT from
IP=10.43.1.112:35783 (IP=10.43.1.112:389)
Jun  3 22:55:19 ldap02e slapd[16804]: conn=1072 op=0 EXT
oid=1.3.6.1.4.1.1466.20037
Jun  3 22:55:19 ldap02e slapd[16804]: conn=1072 op=0 STARTTLS
Jun  3 22:55:19 ldap02e slapd[16804]: conn=1072 op=0 RESULT oid= err=0
etime=0.000104 text=
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 fd=20 TLS established
tls_ssf=256 ssf=256 tls_proto=TLSv1.2 tls_cipher=AES256-SHA256
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=1 BIND
dn="uid=zimbra,cn=admins,cn=zimbra" method=128
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=1 BIND
dn="uid=zimbra,cn=admins,cn=zimbra" mech=SIMPLE ssf=0
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=1 RESULT tag=97 err=0
etime=0.000166 text=
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=2 SRCH
base="cn=ldap02e.zimbra.com,cn=servers,cn=zimbra" scope=0 deref=0
filter="(objectClass=*)"
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=2 SEARCH RESULT tag=101 err=0
etime=0.000415 nentries=1 text=
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=3 SRCH
base="cn=config,cn=zimbra" scope=0 deref=0 filter="(jejectClass=*)"
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 op=3 SEARCH RESULT tag=101 err=0
etime=0.000987 nentries=1 text=
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1072 fd=20 closed (connection lost)
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:fnfo: Stopping proxy via
zmcontrol
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:info: Stopping memcached via
zmcontrol
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:info: Stopping mailbox via
zmcontrol
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:info: Stopping convertd via
zmcontrol
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:info: Stopping logger via
zmcontrol
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:info: Stopping dnscache via
zmcontrol
Jun  3 22:55:20 ldap02e zimbramon[8434]: 8434:info: Stopping ldap via zmcontrol
Jun  3 22:55:20 ldap02e slapd[16804]: daemon: shutdown requested and initiated.
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1009 fd=16 closed (writetimeout)
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1001 fd=17 closed (writetimeout)
Jun  3 22:55:20 ldap02e slapd[16804]: conn=1002 fd=18 closed (writetimeout)
Jun  3 22:55:20 ldap02e slapd[16804]: slapd shutdown: waiting for 3
operations/tasks to finish
Jun  3 22:55:20 ldap02e slapd[16804]: slap_queue_csn: queueing 0x57ea9c0
20160603194926.427963Z#000000#001#000000
Jun  3 22:55:20 ldap02e slapd[16804]: slap_graduate_commit_csn: removing
0x57ea9c0 20160603194926.427963Z#000000#001#000000
Jun  3 22:55:20 ldap02e slapd[16804]: slap_graduate_commit_csn: removing
0xcbdc480 20160603194926.427963Z#000000#001#000000
Jun  3 22:55:20 ldap02e slapd[16804]: syncrepl_message_to_op: rid=100 be_modify
cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0)
Jun  3 22:55:20 ldap02e slapd[16804]: do_syncrepl: rid=100 rc -2 retrying

zimbra@ldap02e:~$ date
Fri Jun  3 23:16: U UTC 2016

(so we can see about 20 minutes has passed)

Full backtrace of all threads:


Thread 4 (Thread 0x7f146ac9d700 (LWP 16805)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x00007f3c70fe8171 in ldap_pvt_thread_cond_wait (cond=0x1fa0038,
mutex=0x1fa0010) at thr_posix.c:277
No locals.
#2  0x00007f3c70fe63c2 in ldap_pvt_thread_pool_destroy (tpool=0x7618c0
<connection_pool>, run_pending=1) at tpool.c:817
        pool = 0x1f763c0
        pptr = 0x1f763c0
        pq = 0x1fa0000
        task = 0x7f3c716a61c8
        i = 0
#3  0x0000000000438967 in slapd_daemon_task (ptr=0x1d7bce8) at daemon.c:2829
        l = 3
        last_idle_check = 1464372736
        ebadf = 0
        tid = 0
#4  0x00007f3c70552184 in start_thread (arg=0x7f146ac9d700) at
pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f146ac9d700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139725667686144,
-1093867468031317215, 0, 0, 139725667686848, 139725667686144,
1078920827726146337, 1056426161274956577},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data =
{prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#5  0x00007f3c7027f37d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 3 (Thread 0x7f1468498700 (LWP 16810)):
#0  0x00007f3c705593ad in read () at ../sysdeps/unix/syscall-template.S:81
No locals.
#1  0x00007f3c70dd2435 in sb_stream_read (sbiod=0x5d36630, buf=0x5a3c057,
len=433) at sockbuf.c:490D0D
        __PRETTY_FUNCTION__ = "sb_stream_read"
#2  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x5d36d20, buf=0x5a3c057,
len=433) at sockbuf.c:829
        ret = 79
        ebuf = "PjIh\024\177\000\000\017\000\000\000\000\000\000\000`\016\000\000\000\000\000\000'\000\000\000\000\000\000\000\250\062H\004\000\000\000\000'\000\000\000\000\000\000\000\240\361H\004\000\000\000\000P\026u\016\000\000\000\000\000\001\000\000\000\000\000\000\001\350#p<\177\000\000\000\000\000\000\000\000\000\0006364\037\000\000\000\000\000\000\006\000\000\000\000\000\000\000hxIh\t\000\000\000\300lIh\024\177\000\000\220jIh\024\177\000"
#3  0x00007f3c7101ebd1 in tlso_bio_read (b=0x5a93110,
    buf=0x5a3c057 "\004\areqType1\b\004\006modify02\004\005reqDN1)\004'uid=gtillman,ou=people,dc=zimbra,dc=com0\201\317\004\006reqMod1\201\304\004:zimbraAuthTokens:-
1988626989|1464372357970|8.7.0_RC1_1601\004\063entryCSN:=
20160527182235.762156Z#000000#003#000000\004."..., len=433) at tls_o.c:721
        p = 0x5a6caa0
        ret = 79
#4  0x00007f3c6f19988b in BIO_read () from
/opt/zimbra/common/lib/libcrypto.so.1.0.0
No symbol table info available.
#5  0x00007f3c6f501ffc in ssl3_read_n () from
/opt/zimbra/common/lib/libssl.so.1.0.0
No symbol table info available.
#6  0x00007f3c6f503ebf in ssl3_read_bytes () from
/opt/zimbra/common/lib/libssl.so.1.0.0
No symbol table info available.
#7  0x00007f3c6f50033b in ssl3_read () from
/opt/zimbra/common/lib/libssl.so.1.0.0
No symbol table info available.
#8  0x00007f3c7101f093 in tlso_sb_read (sbiod=0x5d382e0, buf=0xcb4f93f, len=8)
at tls_o.c:881
        p = 0x5a6caa0
        ret = 635655159814
        err = 28
        __PRETTY_FUNCTION__ = "tlso_sb_read"
#9  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x5d37800, buf=0xcb4f93f, len=8)
at sockbuf.c:829
        ret = 0
        ebuf = "\000\000\000\000\000\000\000\000\300\211Ih\024\177\000\000\000\207Ih\024\177\000\000\000\000\000\000\000\000\000\000pmIh\024\177\000\000v\202\376p<\177\000\000\000\000\000\000\000\000\000\000\240h%h\024\177\000\000]-K\000\000\000\000\000\300{Ih\024\177\000\000\240mIh\000\000\000\000v\202\376p<\177\000\000\000\000\000\000\000\000\000\000\320mIh\024\177\000\000]-K\000\000\000\000\000\300{Ih\024\177\000"
#10 0x00007f3c70dd2291 in ber_int_sb_read (sb=0x5d363c0, buf=0xcb4f93f, len=8)
at sockbuf.c:423
        ret = 0
        __PRETTY_FUNCTION__ = "ber_int_sb_read"
#11 0x00007f3c70dcebbf in ber_get_next (sb=0x5d363c0, len=0x7f1468496f00,
ber=0xcb4f930) at io.c:532
        sblen = 8
        buf = "\000\000\000\000\000\000"
        tlen = 0
        __PRETTY_FUNCTION__ = "ber_get_next"
#12 0x00007f3c70fea22f in try_read1msg (ld=0x5d36d50, msgid=3, all=0,
lc=0x3d9b320, result=0x7f1468497190) at result.c:491
        ber = 0xcb4f930
        newmsg = 0x0
        l = 0x0
        prev = 0x0
        id = 0
        tag = 0
        len = 0
        foundit = 0
        lr = 0x0
        tmplr = 0x0
        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 =x0x0,
          lr_next = 0x0}
        tmpber = {ber_opts = {lbo_valid = -12608, lbo_options = 474, lbo_debug =
0}, ber_tag = 5341050, ber_len = 0, ber_usertag = 5014619, ber_buf = 0x0,
ber_ptr = 0x0, ber_end = 0x0,
          ber_sos_ptr = 0x574963a4 <error: Cannot access memory at address
0x574963a4>, ber_rwptr = 0x0, ber_memctx = 0x67}
        rc = 0
        refer_cnt = 0
        hadref = 0
        simple_request = 0
        err = 0
        lderr = 0
        __PRETTY_FUNCTION__ = "try_read1msg"
A%A#13 0x00007f3c70fe9e53 in
wait4msg (ld=0x5d36d50, msgid=3, all=0, timeout=0x7f14684971f0,
result=0x7f1468497190) at result.c:362
        lnext = 0x0
        serviced = 1
        lc_ready = 1
        rc = -2
        tv = {tv_sec = 0, tv_usec = 0}
        tv0 = {tv_sec = 0, tv_usec = 0}
        start_time_tv = {tv_sec = 1464427439, tv_usec = 944352}
        tvp = 0x7f14684970a0
        lc = 0x3d9b320
        __PRETTY_FUNCTION__ = "wait4msg"
#14 0x00007f3c70fe9574 in ldap_result (ld=0x5d36d50, msgid=3, all=0,
timeout=0x7f14684971f0, result=0x7f1468497190) at result.c:117
        rc = 0
        __PRETTY_FUNCTION__ = "ldap_result"
#15 0x00000000004bd6b2 in do_syncrep2 (op=0x7f1468497720, si=0x1dacec0) at
syncrepl.c:841
        berbuf = {
          buffer = "\002\000\001", '\000' <repeats 29 times>,
"\340\220\234\r\000\000\000\000\b\221\234\r\000\000\000\000\b\221\234\r", '\000'
<repeats 29 times>, "\240<\004", '\000' <repeats 20 times>,
"\370\201\376p<\177\000\000\300\211Ih\024\177\000\000`\003v\000\000\000\000\000\200sIh\024\175C5C000\000\370\201\376p<\177\000\000\070wIh\024\177\000\000&#531;\237\005\000\000\000\000\360sIh\024\177\000\000W\331\000q<\177\000\000\300sIh\024\177\000\000\034tIh\024\177\000\000\001\000\000\000\001\000\000\000P"...,
ialign = 65538, lalign = 65538,
          falign = 9.18382988e-41, dalign = 3.2380074297143616e-319, palign =
0x10002 <error: Cannot access memory at address 0x10002>}
        ber = 0x7f14684972d0
        msg = 0x0
        syncCookie = {ctxcsn = 0x0, sids = 0x0, numcsns = 0, rid = 0, octet_str
= {bv_len = 0, bv_val = 0x0}, sid = 0, sc_next = {stqe_next = 0x0}}
        syncCookie_req = {ctxcsn = 0x0, sids = 0x0, numcsns = 0, rid = 101,
octet_str = {bv_len = 15, bv_val = 0xcaa5460 "rid=101,sid=004"}, sid = 4,
sc_next = {stqe_next D D 0x0}}
        rc = 0
        err = 0
        modlist = 0x0
        m = 1
        tout_p = 0x7f14684971f0
        tout = {tv_sec = 0, tv_usec = 0}
        refreshDeletes = 0
        empty = "empty"
        __PRETTY_FUNCTION__ = "do_syncrep2"
#16 0x00000000004bdebc in do_syncrepl (ctx=0x7f1468497bc0, arg=0x1d8b220) at
syncrepl.c:1561
        rtask = 0x1d8b220
        si = 0x1dacec0
        conn = {c_struct_state = SLAP_C_UNINITIALIZED, c_conn_state =
SLAP_C_INVALID, c_conn_idx = -1, c_sd = 0, c_close_reason = 0x0, c_mutex =
{__data = {__lock = 0, __count = 0,
              __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0,
__list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>,
__align = 0}, c_sb = 0x0,
          c_starttime = 0, c_activitytime = 0, c_connid = 18446744073709551615,
c_peer_domain = {bv_len = 0, bv_val = 0x4f9b70 ""}, c_peer_name = {bv_len = 0,
bv_val = 0x4f9b70 ""},
          c_listener = 0x501d00 <dummy_list>, c_sasl_bind_mech = {bv_len = 0,
bv_val = 0x0}, c_sasl_dn = {bv_len = 0, bv_val = 0x0}, c_sasl_authz_dn = {bv_len
= 0, bv_val = 0x0},
          c_authz_backend = 0x0, c_authz_cookie = 0x0, c_authz = {sai_method =
0, sai_mech = {bv_len = 0, bv_val = 0x0}, sai_dn = {bv_len = 0, bv_val = 0x0},
sai_ndn = {bv_len = 0,
              bv_val = 0x0}, sai_ssf = 0, sai_transport_ssf = 0, sai_tls_ssf =
0, sai_sasl_ssf = 0}, c_protocol = 0, c_ops = {stqh_first = 0x0, stqh_last =
0x0}, c_pending_ops = {
            stqh_first = 0x0, stqh_last = 0x0}, c_write1_mutex = {__data =
{__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0,
__elision = 0, __list = {
                __prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39
times>, __align = 0}, c_write1_cv = {__data %3{_B__lock = 0, __futex = 0,
__total_seq = 0, __wakeup_seq = 0,
              __woken_seq = 0, __mutex = 0x0, __nwaiters = 0, __broadcast_seq =
0}, __size = '\000' <repeats 47 times>, __align = 0}, c_write2_mutex = {__data =
{__lock = 0, __count = 0,
              __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0,
__list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>,
__align = 0}, c_write2_cv = {
            __data = {__lock = 0, __futex = 0,_t_total_seq = 0, __wakeup_seq =
0, __woken_seq = 0, __mutex = 0x0, __nwaiters = 0, __broadcast_seq = 0}, __size
= '\000' <repeats 47 times>,
            __align = 0}, c_currentber = 0x0, c_writers = 0, c_writing = 0
'\000', c_sasl_bind_in_progress = 0 '\000', c_writewaiter = 0 '\000', c__t_tls =
0 '\000',
          c_needs_tls_accept = 0 '\000', c_sasl_layers = 0 '\000', c_sasl_done =
0 '\000', c_sasl_authctx = 0x0, c_sasl_sockctx = 0x0, c_sasl_extra = 0x0,
c_sasl_bindop = 0x0,
          c_pagedresults_state = {ps_be = 0x0, ps_size = 0, ps_count = 0,
ps_cookie = 0, ps_cookieval = {bv_len = 0, bv_val = 0x0}}, c_n_ops_received = 0,
c_n_ops_executing = 0,
          c_n_ops_pending = 0, c_n_ops_completed = 0, c_n_get = 0, c_n_read = 0,
c_n_write = 0, c_extensions = 0x0, c_clientfunc = 0x0, c_clientarg = 0x0,
          c_send_ldap_result = 0x452d9a <slap_send_ldap_result>,
c_send_search_entry = 0x453c11 <slap_send_search_entry>, c_send_search_reference
= 0x455ec7 <slap_send_search_reference>,
          c_send_ldap_extended = 0x4536fa <slap_send_ldap_extended>,
c_send_ldap_intermediate = 0x4539fc <slap_send_ldap_intermediate>}
        opbuf = {ob_op = {o_hdr = 0x7f1468497890, o_tag = 102, o_time =
1464427428, o_tincr = 740798, o_bd = 0x1fa7740, o_req_dn = {bv_len = 39, bv_val
= 0xdd2ab50 ""}, o_req_ndn = {
              bv_len = 39, bv_val = 0xbfb1600 "\260a\301\f"}, o_request =
{oq_add = {rs_modlist = 0xfc28980, rs_e = 0x0}, oq_bind = {rb_method =
264407424, rb_cred = {bv_len = 0,
                  bv_val = 0x0}, rb_edn = {bv_len = 0, bv_val3D3D 0x0}, rb_ssf =
0, rb_mech = {bv_len = 0, bv_val = 0x0}}, oq_compare = {rs_ava = 0xfc28980},
oq_modify = {rs_mods = {
                  rs_modlist = 0xfc28980, rs_no_opattrs = 0 '\000'},
rs_increment = 0}, oq_modrdn = {rs_mods = {rs_modlist = 0xfc28980, rs_no_opattrs
= 0 '\000'}, rs_deleteoldrdn = 0,
                rs_newrdn = {bv_len = 0, bv_val = 0x0}, rs_nnewrdn = {bv_len =
0, bv_val = 0x0}, rs_newSup = 0x0, rs_nnewSup = 0x0}, oq_search = {rs_scope =
264407424, rs_deref = 0,
                rs_slimit = 0, rs_tlimit = 0, rs_limit = 0x0, rs_attrsonly = 0,
rs_attrs = 0x0, rs_filter = 0x0, rs_filterstr = {bv_len = 0, bv_val = 0x0}},
oq_abandon = {
                rs_msgid = 264407424}, oq_cancel = {rs_msgid = 264407424},
oq_extended = {rs_reqoid = {bv_len = 264407424, bv_val = 0x0}, rs_flags = 0,
rs_reqdata = 0x0}, oq_pwdexop = {
                rs_extended = {rs_reqoid = {bv_len = 264407424, bv_val = 0x0},
rs_flags = 0, rs_reqdata = 0x0}, rs_old = {bv_len = 0, bv_val = 0x0}, rs_new =
{bv_len = 0, bv_val = 0x0},
                rs_mods = 0x0, rs_modtail = 0x0}}, o_abandon = 0, o_cancel = 0,
o_groups = 0x0, o_do_not_cache = 0 '\000', o_is_auth_check = 0 '\000',
o_dont_replicate = 0 '\000',
            o_acl_priv = ACL_NONE, o_nocaching = 0 '\000', o_delete_glue_parent
= 0 '\000', o_no_schema_check = 1 '\001', o_no_subordinate_glue = 0 '\000',
            o_ctrlflag = '\000' <repeats 14 times>, "\002", '\000' <repeats 16
times>, o_controls = 0x7f14684979d8, o_authz = {sai_method D D 0, sai_mech =
{bv_len = 0, bv_val = 0x0},
              sai_dn = {bv_len = 9, bv_val = 0x23e8a60 "cn=config"}, sai_ndn =
{bv_len = 9, bv_val = 0x23e8a80 "cn=config"}, sai_ssf = 0, sai_transport_ssf =
0, sai_tls_ssf = 0,
              sai_sasl_ssf = 0}, o_ber = 0x0, o_res_ber = 0x0, o_callback =
0x7f1468496f70, o_ctrls = 0x0, o_csn = {bv_len = 0, bv_val = 0x0}, o_private =
0x0, o_extra = {
              slh_first = 0x0}, o_next = {stqe_next = 0x0}}, ob_hdr = {oh_opid =
0, oh_connid = 101,hoh_conn = 0x7f1468497460, oh_msgid = 0, oh_protocol = 0,
oh_tid = 139725625722624,
            oh_threadctx = 0x7f1468497bc0, oh_tmpmemctx = 0x43ca000,
oh_tmpmfuncs = 0x75e3c0 <slap_sl_mfuncs>, oh_counters = 0x7618e0
<slap_counters>,
            oh_log_prefix = "conn=-1 op=0", '\000' <repeats 243 times>},
ob_controls = {0x0 <repeats 17 times>, 0x7f1468497240, 0x0 <repeats 14 times>}}
        op = 0x7f1468497720
        rc = 0
        dostop = 0
        s = 19
        i = 1
        defer = 1
        fail = 0
        freeinfo = 0
        be = 0x1fa7740
#17 0x000000000043c3ae in connection_read_thread (ctx=0x7f1468497bc0, argv=0x13)
at connection.c:1273
        rc = 0
        cri = {op = 0x0, func = 0x4bd8b4 <do_syncrepl>, arg = 0x1d8b220, ctx =
0x7f1468497bc0, nullop = 0}
        %3= 19
#18 0x00007f3c70fe6a75 in ldap_int_thread_pool_wrapper (xpool=0x1fa0000) at
tpool.c:956
        pq = 0x1fa0000
        pool = 0x1f763c0
        task = 0x3db4520
        work_list = 0x1fa0070
        ctx = {utu_pq = 0x1fa0000, ltu_id = 139725625722624, ltu_key = {{ltk_key
= 0x4b2d5d <slap_sl_mem_init>, ltk_data = 0x43ca000, ltk_free = 0x4b2b82
<slap_sl_mem_destroy>}, {
              ltk_key = 0x1f83300, ltk_data = 0x44ce000, ltk_free =
0x7f3c6bb23f12 <mdb_reader_free>}, {ltk_key = 0x7f3c6bb18ec6 <search_stack>,
ltk_data = 0x47d8000,
              ltk_free = 0x7f3c6bb18ea3 <search_stack_free>}, {ltk_key =
0x7f3c6bb1589f <scope_chunk_get>, ltk_data = 0x44d8000, ltk_free =
0x7f3c6bb15857 <scope_chunk_free>}, {
A0A              ltk_key = 0x1f82c00,
ltk_data = 0x44cfa00, ltk_free = 0x7f3c6bb23f12 <mdb_reader_free>}, {ltk_key =
0x43b82b <conn_counter_init>, ltk_data = 0x1f83c00,
              ltk_free = 0x43b67d <conn_counter_destroy>}, {ltk_key = 0x457375
<slap_op_free>, ltk_data = 0x2562d00, ltk_free = 0x4572c8 <slap_op_q_destroy>},
{ltk_key = 0x0,
              ltk_data = 0x602d600, ltk_free = 0x0}, {ltk_key = 0x0, ltk_data =
0x0, ltk_free = 0x0} <repeats 24 times>}}
        kctx = 0x0
        i = 32
        keyslot = 875
        hash = 521230187
        pool_lock = 0
        freeme = 0
        __PRETTY_FUNCTION__ = "ldap_int_thread_pool_wrapper"
#19 0x00007f3c70552184 in start_thread (arg=0x7f1468498700) at
pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f1468498700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139725625722624,
-1093867468031317215, 0, 0, 139725625723328, 139725625722624,
1078926329042381601, 1056426161274956577},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data =
{prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#20 0x00007f3c7027f37d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 2 (Thread 0x7f1467c97700 (LWP 16812)):
#0  0x00007f3c705593ad in read () at ../sysdeps/unix/syscall-template.S:81
No locals.
#1  0x00007f3c70dd2435 in sb_stream_read (sbiod=0x3dac8b0, buf=0x23cc1a8,
len=96) at sockbuf.c:493
        __PRETTY_FUNCTION__ = "sb_stream_read"
#2  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x3dac850, buf=0x23cc1a8, len=96)
at sockbuf.c:829
        ret = 416
        ebuf = "PZ\311g\024\177\000\000\017\000\000\000\000\000\000\000`\016\000\000\000\000\000\000'\000\000\000\000\000\000\000\230\264\343\005\000\000\000\000'\000\000\000\000\000\000\000P~\344\005\000\000\000\000@C5Cru\016\000\000\000\000\000\001\000\000\000\000\000\000\001\350#p<\177\000\000\000\000\000\000\000\000\000\000\364\037\000\000\000\000\000\000\006\000\000\000\000\000\000\000hh\311g\n\000\000\000\300\\\311g\024\177\000\000\220Z\311g\024\177\000"
#3  0x00007f3c7101ebd1 in tlso_bio_read (b=0x244b2d0,
    buf=0x23cc1a8 "\240F0D\004\030\061.3.6.1.4.1.4203.1.9.1.2\004(0&\n\001\001\004\020\004@\320&\270\206\020\065\223\244\347B\322&#1507;\327\004\017rid=102,sid=001&#52715;\272\005\324a`\346\343\373\335\062\065\223\a\363\363Sv\003\003\003\003\063.1.9.1.2\004(0&\n\001\001\004\020\003\362\377\004\270\206\020\065\223\236\347B\322&#1507;\327\004\017rid=102,sid=001\027&#1500;{\026g\264\262\210\331U]\330#\020u\241&#642;\206\b\b\b\b\b\b\b\b\bntryCSN:=
20160527182329"..., len=96% a at tls_o.c:721
        p = 0x3da51e0
        ret = 416
#4  0x00007f3c6f19988b in BIO_read () from
/opt/zimbra/common/lib/libcrypto.so.1.0.0
No symbol table info available.
#5  0x00007f3c6f501ffc in ssl3_read_n () from
/opt/zimbra/common/lib/libssl.so.0.0.0
No symbol table info available.
#6  0x00007f3c6f503ebf in ssl3_read_bytes () from
/opt/zimbra/common/lib/libssl.so.1.0.0
No symbol table info available.
#7  0x00007f3c6f50033b in ssl3_read () from
/opt/zimbra/common/lib/libssl.so.1.0.0
No symbol table info available.
#8  0x00007f3c7101f093 in tlso_sb_read (sbiod=0x3dac820, buf=0xd93bc7f, len=8)
at tls_o.c:881
        p = 0x3da51e0
        ret = 631360192517
        err = 27
        __PRETTY_FUNCTION__ = "tlso_sb_read"
#9  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x3dac880, buf=0xd93bc7f, len=8)
at sockbuf.c:829
        ret = 0
        ebuf = "\000\000\000\000\000\000\000\000\300y\311g\024\177\000\000\000w\311g\024\177\000\000\000\000\000\000\000\000\000\000p]\311g\024\177\0%0\000v\202\376p<\177\000\000\000\000\000\000\000\000\000\000\240]\311g\024\177\000\000]-K\000\000\000\000\000\300k\311g\024\177\000\000\240]\311g\000\000\000\000v\202\376p<\177\000\000\000\000\000\000\000\000\000\000\320]\311g\024\177\000\000]-K\000\000\0%0\000\000\300k\311g\024\177\000"
#10 0x00007f3c70dd2291 in ber_int_sb_read (sb=0x3dabc80, buf=0xd93bc7f, len=8)
at sockbuf.c:423
        ret = 0
        __PRETTY_FUNCTION__ = "ber_int_sb_read"
#11 0x00007f3c70dcebbf in ber_get_next (sb=0x3dabc80, len=7x7f1467c95f00,
ber=0xd93bc70) at io.c:532
        sblen = 8
        buf = "\000\000\000\000\000\000"
        tlen = 0
        __PRETTY_FUNCTION__ = "ber_get_next"
#12 0x00007f3c70fea22f in try_read1msg (ld=0x3dabc50, msgid=3, all=0,
lc=0x1f7d960, result=0x7f1467c96190) at result.c:491
        ber = 0xd93bc70
        newmsg = 0x0
        l = 0x0
        prev = 0x0
        id = 0
        tag = 0
        len = 0
        foundit = 0
        lr = 0x0
        tmplr = 0x0
        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 = -11904, lbo_options = 474, lbo_debug =
0}, ber_tag = 5341050, ber_len = 0, ber_usertag = 5014619, ber_buf = 0x0,
ber_ptr = 0x0, ber_end = 0%0,
          ber_sos_ptr = 0x5748c3eb <error: Cannot access memory at address
0x5748c3eb>, ber_rwptr = 0x0, ber_memctx = 0x67}
        rc = 0
        refer_cnt = 0
        hadref = 0
        simple_request = 0
        err = 0
        lderr = 0
%          __PRETTY_FUNCTION__ = "try_read1msg"
#13 0x00007f3c70fe9e53 in wait4msg (ld=0x3dabc50, msgid=3, all=0,
timeout=0x7f1467c961f0, result=0x7f1467c96190) at result.c:362
        lnext = 0x0
        serviced = 1
        lc_ready = 1
        rc = -2
        tv = {tv_sec = 0, tv_usec = 0}
        tv0 = {tv_sec = 0, tv_usec = 0}
        start_time_tv = {tv_sec = 1464386543, tv_usec = 695070}
        tvp = 0x7f1467c960a0
        lc = 0x1f7d960
        __PRETTY_FUNCTION__ = "wait4msg"
#14 0x007f7f3c70fe9574 in ldap_result (ld=0x3dabc50, msgid=3, all=0,
timeout=0x7f1467c961f0, result=0x7f1467c96190) at result.c:117
        rc = 0
        __PRETTY_FUNCTION__ = "ldap_result"
#15 0x00000000004bd6b2 in do_syncrep2 (op=0x7f1467c96720, si=0x1dad180) at
syncrepl.c:841
        berbuf = {
          buffer = "\002\000\001", '\000' <repeats 29 times>,
"\200\060\207\r\000\000\000\000\250\060\207\r\000\000\000\000\250\060\207\r",
'\000' <repeats 28 times>, "\200\267<\004", '\000' <repeats 20 times>,
"\370\201\376p<\177\000\000\300y\311g\024\177\000\000`\003v\000\000\000\000\000\200c\311g\024\177\000\000\370\201\376p<\177\000\000\070g\311g\024\177\000\000\310y\370\001\000\000\000\000\360c\311g\024\177\000\000W\331\000q<\177\000\000\300c\311g\024\177\000\000\034d\311g\024\177\000\000\001\000\000\000\001\000\000\000"...,
ialign = 65538,
          lalign = 65538, falign = 9.18382988e-41, dalign =
3.2380074297143616e-319, palign = 0x10002 <error: Cannot access memory at
address 0x10002>}
        ber = 0x7f1467c962d0D%0
        msg = 0x0
        syncCookie = {ctxcsn = 0x0, sids = 0x0, numcsns = 0, rid = 0, octet_str
= {bv_len = 0, bv_val = 0x0}, sid = 0, sc_next = {stqe_next = 0x0}}
        syncCookie_req = {ctxcsn = 0x0, sids = 0x0, numcsns = 0, rid = 102,
octet_str = {bv_len = 15, bv_val = 0xc2faf30 "rid=102,sid=001"}, sid = 1,
sc_next = {stqe_next = 0x0}}
        rc = 0
        err = 0
        modlist = 0x0
        m = 1
        tout_p = 0x7f1467c961f0
        tout = {tv_sec = 0,v_v_usec = 0}
        refreshDeletes = 0
        empty = "empty"
        __PRETTY_FUNCTION__ = "do_syncrep2"
#16 0x00000000004bdebc in do_syncrepl (ctx=0x7f1467c96bc0, arg=0x1d8b130) at
syncrepl.c:1561
        rtask = 0x1d8b130
        si = 0x1dad180
A0A        conn = {c_struct_state = SLAP_C_UNINITIALIZED,
c_conn_state = SLAP_C_INVALID, c_conn_idx = -1, c_sd = 0, c_close_reason = 0x0,
c_mutex = {__data = {__lock = 0, __count = 0,
              __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0,
__list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>,
__align = 0}, c_sb = 0x0,
          c_starttime = 0, c_activitytime = 0, c_connid = 18446744073709551615,
c_peer_domain = {bv_len = 0, bv_val = 0x4f9b70 ""}, c_peer_name = {bv_len = 0,
bv_val = 0x4f9b70 ""},
          c_listener = 0x501d00 <dummy_list>, c_sasl_bind_mech = {bv_len = 0,
bv_val = 0x0}, c_sasl_dn = {bv_len = 0, bv_val = 0x0}, c_sasl_authz_dn = {bv_len
= 0, bv_val = 0x0},
          c_authz_backend = 0x0, c_authz_cookie = 0x0, c_authz = {sai_method =
0, sai_mech = {bv_len = 0, bv_val = 0x0}, sai_dn = {bv_len = 0, bv_val = 0x0},
sai_ndn = {bv_len = 0,
              bv_val = 0x0}, sai_ssf = 0, sai_transport_ssf = 0, sai_tls_ssf =
0, sai_sasl_ssf = 0}, c_protocol = 0, c_ops = {stqh_first = 0x0, stqh_last =
0x0}, c_pending_ops = {
            stqh_first = 0x0, stqh_last = 0x0}, c_write1_mutex = {__data =
{__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0,
__elision = 0, __list = {
                __prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39
times>, __align = 0}, c_write1_cv = {__data = {__lock = 0, __futex = 0,
__total_seq = 0, __wakeup_seq = 0,
              __woken_seq = 0, __mutex = 0x0, __nwaiters = 0, __broadcast_seq
=%0}, __size = '\000' <repeats 47 times>, __align = 0}, c_write2_mutex = {__data
= {__lock = 0, __count = 0,
              __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0,
__list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>,
__align = 0}, c_write2_cv = {
            __data = {__lock = 0, __futex = 0, __total_seq = 0, __wakeup_seq =
0, __woken_seq = 0, __mutex = 0x0, __nwaiters = 0, __broadcast_seq = 0}, __size
= '\000' <repeats 47 times>,
            __align = 0}, c_currentber 0x0x0, c_writers = 0, c_writing = 0
'\000', c_sasl_bind_in_progress = 0 '\000', c_writewaiter = 0 '\000', c_is_tls =
0 '\000',
          c_needs_tls_accept = 0 '\000', c_sasl_layers = 0 '\000', c_sasl_done =
0 '\000', c_sasl_authctx = 0x0, c_sasl_sockctx = 0x0, c_sasl_extra = 0x0,
c_sasl_bindop = 0x0,
          c_pagedresults_state = {ps_be = 0x0, ps_size = 0, ps_count = 0,
ps_cookie = 0, ps_cookieval = {bv_len = 0, bv_val = 0x0}}, c_n_ops_received = 0,
c_n_ops_executing = 0,
          c_n_ops_pending = 0, c_n_ops_completed = 0, c_n_get = 0, c_n_read = 0,
c_n_write = 0, c_extensions = 0x0, c_clientfunc = 0x0, c_clientarg = 0x0,
          c_send_ldap_result = 0x452d9a <slap_send_ldap_result>,
c_send_search_entry = 0x453c11 <slap_send_search_entry>, c_send_search_reference
= 0x455ec7 <slap_send_search_reference>,
          c_send_ldap_extended = 0x4536fa <slap_send_ldap_extended>,
c_send_ldap_intermediate = 0x4539fc <slap_send_ldap_intermediate>}
        opbuf = {ob_op = {o_hdr = 0x7f1467c96890, o_tag = 102, o_time =
1464386539, o_tincr = 697802, o_bd = 0x1fa7740, o_req_dn = {bv_len = 39, bv_val
= 0xfad64e0 ""}, o_req_ndn = {
              bv_len = 39, bv_val = 0xfb76000 "`\246\030\f"}, o_request =
{oq_add = {rs_modlist = 0xfb25200, rs_e = 0x0}, oq_bind = {rb_method =
263344640, rb_cred = {bv_len = 0,
                  bv_val = 0x0}, rb_edn = {bv_len = 0, bv_val = 0x0}, rb_ssf =
0, rb_mech = {bv_len = 0, bv_val = 0x0}}, oq_compare = {rs_ava = 0xfb25200},
oq_modify = {rs_mods = {
                  rs_modlist = 0xfb25200, rs_no_opattrs = 0 '\000'},
rs_increment = 0}, oq_modrdn = {rs_mods = {rs_modlist = 0xfb25200, rs_no_opattrs
= 0 '\000'}, rs_deleteoldrdn = 0,
                rs_newrdn = {bv_len = 0, bv_val = 0x0}, rs_nnewrdn = {bv_len =
0, bv_val = 0x0}, rs_newSup = 0x0, rs_nnewSup = 0x0}, oq_search = {rs_scope =
263344640, rs_deref = 0,
                rs_slimit = 0, rs_tlimit = 0, rs_limit = 0x0, rs_attrsonly = 0,
rs_attrs = 0x0, rs_filter = 0x0, rs_filterstr = {bv_len = 0, bv_val = 0x0}},
oq_abandon = {
                rs_msgid = 263344640}, oq_cancel = {rs_msgid = 263344640},
oq_extended = {rs_reqoid = {bv_len = 263344640, bv_val = 0x0}, rs_flags = 0,
rs_reqdata = 0x0}, oq_pwdexop = {
                rs_extended = {rs_reqoid = {bv_len = 263344640, bv_val = 0x0}C C
rs_flags = 0, rs_reqdata = 0x0}, rs_old = {bv_len = 0, bv_val = 0x0}, rs_new =
{bv_len = 0, bv_val = 0x0},
                rs_mods = 0x0, rs_modtail = 0x0}}, o_abandon = 0, o_cancel = 0,
o_groups = 0x0, o_do_not_cache = 0 '\000', o_is_auth_check = 0 '\000',
o_dont_replicate = 0 '\000',
            o_acl_priv = ACL_NONE, o_nocaching = 0 '\000', o_delete_glue_parent
= 0 '\000', o_no_schema_check = 1 '\001', o_no_subordinate_glue = 0 '\000',
            o_ctrlflag = '\000' <repeats 14 times>, "\002", '\000' <repeats 16
times>, o_controls = 0x7f1467c969d8, o_authz = {sai_method = 0, sai_mech =
{bv_len = 0, bv_val = 0x0},
              sai_dn = {bv_len = 9, bv_val = 0x23e8a60 "cn=config"}, sai_ndn =
{bv_len = 9, bv_val = 0x23e8a80 "cn=config"}, sai_ssf = 0, sai_transport_ssf =
0, sai_tls_ssf = 0,
              sai_sasl_ssf = 0}, o_ber = 0x0, o_res_ber = 0x0, o_callback =
0x7f1467c95f70, o_ctrls = 0x0, o_csn = {bv_len = 0, bv_val = 0x0}, o_private =
0x0, o_extra = {
              slh_first = 0x0}, o_next = {stqe_next = 0x0}}, ob_hdr = {oh_opid =
0, oh_connid = 102, oh_conn = 0x7f1467c96460, oh_msgid = 0, oh_protocol = 0,
oh_tid = 139725617329920,
            oh_threadctx = 0x7f1467c96bc0, oh_tmpmemctx = 0x43cb780,
oh_tmpmfuncs = 0x75e3c0 <slap_sl_mfuncs>, oh_counters = 0x7618e0
<slap_counters>,
            oh_log_prefix = "conn=-1 op=0", '\000' <repeats 243 times>},
ob_controls = {0x0 <repeats 17 times>, 0x7f1467c96240, 0x0 <repeats 14 times>}}
        op = 0x7f1467c96720
        rc = 0
        dostop = 0
        s = 15
        i = 1
        defer = 1
        fail = 0
        freeinfo = 0
        be = 0x1fa7740
#17 0x000000000043c3ae in connection_read_thread (ctx=0x7f1467c96bc0, argv=0xf)
at connection.c:1273
        rc = 0
        cri = {op = 0x0, func = 0x4bd8b4 <do_syncrepl>, arg = 0x1d8b130, ctx =
0x7f1467c96bc0, nullop = 0}
        s = 15
#18 0x00007f3c70fe6a75 in ldap_int_thread_pool_wrapper (xpool=0x1fa0000) at
tpool.c:956
        pq = 0x1fa0000
        pool = 0x1f763c0
        task = 0x3db4500
        work_list = 0x1fa0070
        ctx = {ltu_pq = 0x1fa0000, ltu_id = 139725617329920, ltu_key = {{ltk_key
= 0x4b2d5d <slap_sl_mem_init>, ltk_data = 0x43cb780, ltk_free = 0x4b2b82
<slap_sl_mem_destroy>}, {
              ltk_key = 0x1f82c00, ltk_data = 0x5ee4000, ltk_free =
0x7f3c6bb23f12 <mdb_reader_free>}, {ltk_key = 0x43b82b <conn_counter_init>,
ltk_data = 0x25ec700,
              ltk_free = 0x43b67d <conn_counter_destroy>}, {ltk_key = 0x457375
<slap_op_free>, ltk_data = 0x25621c0, ltfreeee = 0x4572c8 <slap_op_q_destroy>},
{ltk_key = 0x1f83300,
              ltk_data = 0x5eea800, ltk_free = 0x7f3c6bb23f12
<mdb_reader_free>}, {ltk_key = 0x7f3c6bb18ec6 <search_stack>, ltk_data =
0xafae000,
              ltk_free = 0x7f3c6bb18ea3 <search_stack_free>}, {ltk_key =
0x7f3c6bb1589f <scope_chunk_get>, ltk_data = 0xacae000, ltk_free =
0x7f3c6bb15857 <scope_chunk_free>}, {
              ltk_key = 0x0, ltk_data = 0x5a17200, ltk_free = 0x0}, {ltk_key =
0x0, ltk_data = 0x0, ltk_free = 0x0} <repeats 24 times>}}
        kctx = 0x0
        i = 32
        keyslot = 410
        hash = 616821146
        pool_lock = 0
        freeme = 0
        __PRETTY_FUNCTION__ = "ldap_int_thread_pool_wrapper"
#19 0x00007f3c70552184 in start_thread (arg=0x7f1467c97700) at
pthread_create.c:312
        __res = <optimized out>
        pd = 0x7f1467c97700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139725617329920,
-1093867468031317215, 0, 0, 139725617330624, 139725617329920,
1078896641691560737, 1056426161274956577},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data =
{prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#20 0x00007f3c7027f37d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

Thread 1 (Thread 0x7f3c71694780 (LWP 16804)):
#0  0x00007f3c7055365b in pthread_join (threadid=139725667686144,
thread_return=0x0) at pthread_join.c:92
        _tid = 16805
        _buffer = {__routine = 0x7f3c70553590 <cleanup>, __arg = 0x7f146ac9dd28,
__canceltype = 1791612672, __prev = 0x0}
        oldtype = 0
        pd = 0x7f146ac9d700
        self = 0x7f3c71694780
        result = 0
#1  0x00007f3c70fe80b2 in ldap_pvt_thread_join (thread=139725667686144,
thread_return=0x0) at thr_posix.c:197
No locals.
#2  0x0000000000438cc0 in slapd_daemon () at daemon.c:2910
        i = 0
        rc = 0
#3  0x0000000000414ce1 in main (argc=9, argv=0x7ffe003b02b8) at main.c:1017
        i = 9
        no_detach = 0
        rc = 0
        urls = 0x1d8a000 "ldap://ldap02e.zimbra.com:389
ldaps://ldap02e.zimbra.com:636 ldapi:///"
        username = 0x1d7a010 "root"
        groupname = 0x0
        sandbox = 0x0
        syslogUser = 128
        pid = 0
        waitfds = {10, 11}
        g_argc = 9
        g_argv = 0x7ffe003b02b8
        configfile = 0x0
        configdir = 0x1d82020 "/opt/zimbra/data/ldap/config"
        serverName = 0x7ffe003b0d78 "slapd"
        serverMode = 1
        scp = 0x0
        scp_entry = 0x0
        debug_unknowns = 0x0
        syslog_unknowns = 0x0
        serverNamePrefix = 0x4f9608 ""
        l = 739235890461816576
        slapd_pid_file_unlink = 1
        slapd_args_file_unlink = 1
        firstopt = 0
        __PRETTY_FUNCTION__ = "main"
(gdb)
Comment 1 Howard Chu 2016-06-08 22:39:28 UTC
quanah@openldap.org wrote:
> Full backtrace of all threads:
>
>
> Thread 4 (Thread 0x7f146ac9d700 (LWP 16805)):
> #0  pthread_cond_wait@@GLIBC_2.3.2 () at
> ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
> No locals.
> #1  0x00007f3c70fe8171 in ldap_pvt_thread_cond_wait (cond=0x1fa0038,
> mutex=0x1fa0010) at thr_posix.c:277
> No locals.
> #2  0x00007f3c70fe63c2 in ldap_pvt_thread_pool_destroy (tpool=0x7618c0
> <connection_pool>, run_pending=1) at tpool.c:817
>          pool = 0x1f763c0
>          pptr = 0x1f763c0
>          pq = 0x1fa0000
>          task = 0x7f3c716a61c8
>          i = 0
> #3  0x0000000000438967 in slapd_daemon_task (ptr=0x1d7bce8) at daemon.c:2829
>          l = 3
>          last_idle_check = 1464372736
>          ebadf = 0
>          tid = 0
> #4  0x00007f3c70552184 in start_thread (arg=0x7f146ac9d700) at
> pthread_create.c:312
>          __res = <optimized out>
>          pd = 0x7f146ac9d700
>          now = <optimized out>
>          unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139725667686144,
> -1093867468031317215, 0, 0, 139725667686848, 139725667686144,
> 1078920827726146337, 1056426161274956577},
>                mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data =
> {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
>          not_first_call = <optimized out>
>          pagesize_m1 = <optimized out>
>          sp = <optimized out>
>          freesize = <optimized out>
>          __PRETTY_FUNCTION__ = "start_thread"
> #5  0x00007f3c7027f37d in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
> No locals.

Thread 4 is waiting for the other threads to finish.
>
> Thread 3 (Thread 0x7f1468498700 (LWP 16810)):
> #0  0x00007f3c705593ad in read () at ../sysdeps/unix/syscall-template.S:81
> No locals.
> #1  0x00007f3c70dd2435 in sb_stream_read (sbiod=0x5d36630, buf=0x5a3c057,
> len=433) at sockbuf.c:490D0D
>          __PRETTY_FUNCTION__ = "sb_stream_read"

Thread 3 is inside OpenSSL, it thinks there are 433 bytes to read on this 
socket and it's waiting for them to arrive. There's not much we can do in 
slapd about this.

> #2  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x5d36d20, buf=0x5a3c057,
> len=433) at sockbuf.c:829
>          ret = 79
>          ebuf = "PjIh\024\177\000\000\017\000\000\000\000\000\000\000`\016\000\000\000\000\000\000'\000\000\000\000\000\000\000\250\062H\004\000\000\000\000'\000\000\000\000\000\000\000\240\361H\004\000\000\000\000P\026u\016\000\000\000\000\000\001\000\000\000\000\000\000\001\350#p<\177\000\000\000\000\000\000\000\000\000\0006364\037\000\000\000\000\000\000\006\000\000\000\000\000\000\000hxIh\t\000\000\000\300lIh\024\177\000\000\220jIh\024\177\000"
> #3  0x00007f3c7101ebd1 in tlso_bio_read (b=0x5a93110,
>      buf=0x5a3c057 "\004\areqType1\b\004\006modify02\004\005reqDN1)\004'uid=gtillman,ou=people,dc=zimbra,dc=com0\201\317\004\006reqMod1\201\304\004:zimbraAuthTokens:-
> 1988626989|1464372357970|8.7.0_RC1_1601\004\063entryCSN:=
> 20160527182235.762156Z#000000#003#000000\004."..., len=433) at tls_o.c:721
>          p = 0x5a6caa0
>          ret = 79
> #4  0x00007f3c6f19988b in BIO_read () from
> /opt/zimbra/common/lib/libcrypto.so.1.0.0
> No symbol table info available.
> #5  0x00007f3c6f501ffc in ssl3_read_n () from
> /opt/zimbra/common/lib/libssl.so.1.0.0
> No symbol table info available.
> #6  0x00007f3c6f503ebf in ssl3_read_bytes () from
> /opt/zimbra/common/lib/libssl.so.1.0.0
> No symbol table info available.
> #7  0x00007f3c6f50033b in ssl3_read () from
> /opt/zimbra/common/lib/libssl.so.1.0.0
> No symbol table info available.
> #8  0x00007f3c7101f093 in tlso_sb_read (sbiod=0x5d382e0, buf=0xcb4f93f, len=8)
> at tls_o.c:881
>          p = 0x5a6caa0
>          ret = 635655159814
>          err = 28
>          __PRETTY_FUNCTION__ = "tlso_sb_read"
> #9  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x5d37800, buf=0xcb4f93f, len=8)
> at sockbuf.c:829
>          ret = 0
>          ebuf = "\000\000\000\000\000\000\000\000\300\211Ih\024\177\000\000\000\207Ih\024\177\000\000\000\000\000\000\000\000\000\000pmIh\024\177\000\000v\202\376p<\177\000\000\000\000\000\000\000\000\000\000\240h%h\024\177\000\000]-K\000\000\000\000\000\300{Ih\024\177\000\000\240mIh\000\000\000\000v\202\376p<\177\000\000\000\000\000\000\000\000\000\000\320mIh\024\177\000\000]-K\000\000\000\000\000\300{Ih\024\177\000"
> #10 0x00007f3c70dd2291 in ber_int_sb_read (sb=0x5d363c0, buf=0xcb4f93f, len=8)
> at sockbuf.c:423
>          ret = 0
>          __PRETTY_FUNCTION__ = "ber_int_sb_read"
> #11 0x00007f3c70dcebbf in ber_get_next (sb=0x5d363c0, len=0x7f1468496f00,
> ber=0xcb4f930) at io.c:532
>          sblen = 8
>          buf = "\000\000\000\000\000\000"
>          tlen = 0
>          __PRETTY_FUNCTION__ = "ber_get_next"
> #12 0x00007f3c70fea22f in try_read1msg (ld=0x5d36d50, msgid=3, all=0,
> lc=0x3d9b320, result=0x7f1468497190) at result.c:491
>          ber = 0xcb4f930
>          newmsg = 0x0
>          l = 0x0
>          prev = 0x0
>          id = 0
>          tag = 0
>          len = 0
>          foundit = 0
>          lr = 0x0
>          tmplr = 0x0
>          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 =x0x0,
>            lr_next = 0x0}
>          tmpber = {ber_opts = {lbo_valid = -12608, lbo_options = 474, lbo_debug =
> 0}, ber_tag = 5341050, ber_len = 0, ber_usertag = 5014619, ber_buf = 0x0,
> ber_ptr = 0x0, ber_end = 0x0,
>            ber_sos_ptr = 0x574963a4 <error: Cannot access memory at address
> 0x574963a4>, ber_rwptr = 0x0, ber_memctx = 0x67}
>          rc = 0
>          refer_cnt = 0
>          hadref = 0
>          simple_request = 0
>          err = 0
>          lderr = 0
>          __PRETTY_FUNCTION__ = "try_read1msg"A%A#13 0x00007f3c70fe9e53 in
> wait4msg (ld=0x5d36d50, msgid=3, all=0, timeout=0x7f14684971f0,
> result=0x7f1468497190) at result.c:362
>          lnext = 0x0
>          serviced = 1
>          lc_ready = 1
>          rc = -2
>          tv = {tv_sec = 0, tv_usec = 0}
>          tv0 = {tv_sec = 0, tv_usec = 0}
>          start_time_tv = {tv_sec = 1464427439, tv_usec = 944352}
>          tvp = 0x7f14684970a0
>          lc = 0x3d9b320
>          __PRETTY_FUNCTION__ = "wait4msg"
> #14 0x00007f3c70fe9574 in ldap_result (ld=0x5d36d50, msgid=3, all=0,
> timeout=0x7f14684971f0, result=0x7f1468497190) at result.c:117
>          rc = 0
>          __PRETTY_FUNCTION__ = "ldap_result"
> #15 0x00000000004bd6b2 in do_syncrep2 (op=0x7f1468497720, si=0x1dacec0) at
> syncrepl.c:841

> Thread 2 (Thread 0x7f1467c97700 (LWP 16812)):
> #0  0x00007f3c705593ad in read () at ../sysdeps/unix/syscall-template.S:81
> No locals.
> #1  0x00007f3c70dd2435 in sb_stream_read (sbiod=0x3dac8b0, buf=0x23cc1a8,
> len=96) at sockbuf.c:493
>          __PRETTY_FUNCTION__ = "sb_stream_read"
> #2  0x00007f3c70dd2e56 in sb_debug_read (sbiod=0x3dac850, buf=0x23cc1a8, len=96)
> at sockbuf.c:829
>          ret = 416
>          ebuf = "PZ\311g\024\177\000\000\017\000\000\000\000\000\000\000`\016\000\000\000\000\000\000'\000\000\000\000\000\000\000\230\264\343\005\000\000\000\000'\000\000\000\000\000\000\000P~\344\005\000\000\000\000@C5Cru\016\000\000\000\000\000\001\000\000\000\000\000\000\001\350#p<\177\000\000\000\000\000\000\000\000\000\000\364\037\000\000\000\000\000\000\006\000\000\000\000\000\000\000hh\311g\n\000\000\000\300\\\311g\024\177\000\000\220Z\311g\024\177\000"
> #3  0x00007f3c7101ebd1 in tlso_bio_read (b=0x244b2d0,
>      buf=0x23cc1a8 "\240F0D\004\030\061.3.6.1.4.1.4203.1.9.1.2\004(0&\n\001\001\004\020\004@\320&\270\206\020\065\223\244\347B\322&#1507;\327\004\017rid=102,sid=001&#52715;\272\005\324a`\346\343\373\335\062\065\223\a\363\363Sv\003\003\003\003\063.1.9.1.2\004(0&\n\001\001\004\020\003\362\377\004\270\206\020\065\223\236\347B\322&#1507;\327\004\017rid=102,sid=001\027&#1500;{\026g\264\262\210\331U]\330#\020u\241&#642;\206\b\b\b\b\b\b\b\b\bntryCSN:=
> 20160527182329"..., len=96% a at tls_o.c:721
>          p = 0x3da51e0
>          ret = 416
> #4  0x00007f3c6f19988b in BIO_read () from
> /opt/zimbra/common/lib/libcrypto.so.1.0.0
> No symbol table info available.

Thread 2 is in the same state as thread 3.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

Comment 2 Quanah Gibson-Mount 2016-06-09 15:47:02 UTC
--On Wednesday, June 08, 2016 11:39 PM +0000 hyc@symas.com wrote:

> Thread 3 is inside OpenSSL, it thinks there are 433 bytes to read on this
> socket and it's waiting for them to arrive. There's not much we can do in
> slapd about this.

Going back through my notes on when we hit this before with customers, the 
following are the steps necessary to trigger these deadlocks:

a) Must have 2+ replication agreements per node.  This will not occur in 2 
MMR node environments

b) starttls is used in all the replication agreements

c) There needs to be fairly consistent write traffic

After some point of time, slapd will then deadlock on shutdown.  Or, if 
allowed to run long enough, it will grind completely to a halt (2-3 weeks, 
depending on traffic).

This started after we upgraded to openssl 1.0.1j.  It is continuing to 
occur with openssl 1.0.2h (just to ntoe).

--Quanah


--

Quanah Gibson-Mount
Release and QA Engineer
<http://www.openldap.org>

Comment 3 OpenLDAP project 2017-04-03 18:38:41 UTC
OpenSSL bug?
Comment 4 Quanah Gibson-Mount 2017-04-03 18:38:41 UTC
changed notes
moved from Incoming to Software Bugs
Comment 5 Quanah Gibson-Mount 2020-03-22 22:56:18 UTC
appears to be openssl bug