--On Friday, November 28, 2008 7:40 PM +0000 quanah(a)zimbra.com wrote:
>
>
> --On November 28, 2008 11:35:45 AM -0800 Quanah Gibson-Mount
> <quanah(a)zimbra.com> wrote:
Latest backtrace, with the patch from HEAD about idletimeout, we get:
(gdb) bt
#0 0x0000003fca02e21d in raise () from /lib64/tls/libc.so.6
#1 0x0000003fca02fa1e in abort () from /lib64/tls/libc.so.6
#2 0x0000003fca027ae1 in __assert_fail () from /lib64/tls/libc.so.6
#3 0x000000000042b5c1 in connection_close (c=0x3b69520) at connection.c:877
#4 0x0000000000429e7d in connections_timeout_idle (now=1228167365) at
connection.c:242
#5 0x0000000000428097 in slapd_daemon_task (ptr=0x0) at daemon.c:2039
#6 0x0000003fca90610a in start_thread () from /lib64/tls/libpthread.so.0
#7 0x0000003fca0c68c3 in clone () from /lib64/tls/libc.so.6
#8 0x0000000000000000 in ?? ()
Looking at the connection, we see:
(gdb) frame 3
#3 0x000000000042b5c1 in connection_close (c=0x3b69520) at connection.c:877
877 connection.c: No such file or directory.
in connection.c
(gdb) print *c
$1 = {c_struct_state = 2, c_conn_state = 3, c_conn_idx = 28, c_close_reason
= 0x4bea5b "?", c_mutex = {__m_reserved = 2, __m_count = 0, __m_owner =
0x100002068, __m_kind = 0, __m_lock = {
__status = 0, __spinlock = 0}}, c_sb = 0x13b4d860, c_starttime =
1228167365, c_activitytime = 1228167365, c_connid = 3120, c_peer_domain =
{bv_len = 7,
bv_val = 0xdfac1b0 "unknown"}, c_peer_name = {bv_len = 23, bv_val =
0x108dc558 "IP=192.168.58.225:53050"}, c_listener = 0x88df00,
c_sasl_bind_in_progress = 0, 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 = 128, 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
= 0x64abc00, stqh_last = 0x64abd58}, c_pending_ops = {stqh_first = 0x0,
stqh_last = 0x3b69650},
c_write_mutex = {__m_reserved = 0, __m_count = 0, __m_owner = 0x0,
__m_kind = 0, __m_lock = {__status = 0, __spinlock = 0}}, c_write_cv =
{__c_lock = {__status = 3556232921088,
__spinlock = 414}, __c_waiting = 0x19e, __padding =
"\236\001\000\000\000\000\000\0008\225�\003\000\000\000", __align =
0}, c_currentber = 0xe032000, c_writewaiter = 0,
c_is_tls = 0, c_needs_tls_accept = 0, c_sasl_layers = 0, c_sasl_done = 0,
c_sasl_authctx = 0xe035400, c_sasl_sockctx = 0x0, c_sasl_extra = 0x669cac8,
c_sasl_bindop = 0x0,
c_pagedresults_state = {ps_be = 0x0, ps_size = 0, ps_cookie = 0, ps_count
= 0}, c_n_ops_received = 1, c_n_ops_executing = 1, c_n_ops_pending = 0,
c_n_ops_completed = 0, c_n_get = 1,
c_n_read = 1, c_n_write = 0, c_pb = 0x0, c_extensions = 0x0, c_clientfunc
= 0, c_clientarg = 0x0, c_send_ldap_result = 0x43ea8c
<slap_send_ldap_result>,
c_send_search_entry = 0x43f787 <slap_send_search_entry>,
c_send_search_reference = 0x44188d <slap_send_search_reference>,
c_send_ldap_extended = 0x43f2fa <slap_send_ldap_extended>,
c_send_ldap_intermediate = 0x43f57e <slap_send_ldap_intermediate>}
So this was file descriptor 28.
This is definitely the same assert as before in connection.c:
assert( c->c_conn_state == SLAP_C_CLOSING );
being line 877.
Line 242 is:
if( difftime( c->c_activitytime+global_idletimeout, now) <
0 ) {
/* close it */
connection_closing( c, "idletimeout" );
--> connection_close( c );
i++;
}
The log file shows:
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]: 28r
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: read active on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:04 ldap slapd[8292]:
Dec 2 03:06:04 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:06:04 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:06:04 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:06:05 ldap slapd[8292]: daemon: activity on:
Dec 2 03:06:05 ldap slapd[8292]:
Dec 2 03:06:05 ldap slapd[8292]: daemon: hangup on 28
Dec 2 03:06:05 ldap slapd[8292]: connection_closing: readying conn=3049
sd=28 for close
Dec 2 03:06:05 ldap slapd[8292]: connection_resched: attempting closing
conn=3049 sd=28
Dec 2 03:06:05 ldap slapd[8292]: daemon: removing 28
Dec 2 03:06:05 ldap slapd[8292]: conn=3049 fd=28 closed (idletimeout)
Dec 2 03:06:05 ldap slapd[8292]: daemon: listen=7, new connection on 28
Dec 2 03:06:05 ldap slapd[8292]: daemon: added 28r (active) listener=(nil)
Dec 2 03:06:05 ldap slapd[8292]: conn=3120 fd=28 ACCEPT from
IP=192.168.58.225:53050 (IP=192.168.58.179:389)
Dec 2 03:06:05 ldap slapd[8292]: conn=3120 op=0 BIND
dn="uid=zimbra,cn=admins,cn=zimbra" method=128
And here's the start of the previous connection on descriptor 28:
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 busy
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: listen=7, new connection on 28
Dec 2 03:03:53 ldap slapd[8292]: daemon: added 28r (active) listener=(nil)
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 fd=28 ACCEPT from
IP=192.168.61.35:57352 (IP=192.168.58.179:389)
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 2 descriptors
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]: 28r
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: read active on 28
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=0 STARTTLS
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=0 RESULT oid= err=0 text=
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]: 28r
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: read active on 28
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]: 28r
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: read active on 28
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=1 BIND
dn="uid=zmreplica,cn=admins,cn=zimbra" method=128
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=1 BIND
dn="uid=zmreplica,cn=admins,cn=zimbra" mech=SIMPLE ssf=0
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=1 RESULT tag=97 err=0 text=
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]: 28r
Dec 2 03:03:53 ldap slapd[8292]:
Dec 2 03:03:53 ldap slapd[8292]: daemon: read active on 28
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=7 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: daemon: epoll: listen=8 active_threads=1
tvp=zero
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=2 SRCH base="cn=accesslog"
scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))"
Dec 2 03:03:53 ldap slapd[8292]: conn=3049 op=2 SRCH attr=reqDN reqType
reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on 1 descriptor
Dec 2 03:03:53 ldap slapd[8292]: daemon: activity on:
Dec 2 03:03:53 ldap slapd[8292]:
Then nothing logged again until the first segment quoted where it crashed.
--Quanah
--
Quanah Gibson-Mount
Principal Software Engineer
Zimbra, Inc
--------------------
Zimbra :: the leader in open source messaging and collaboration