[389-users] Lots of abandoned connections from sssd

Wed Nov 12 00:01:53 UTC 2014

On 11/05/2014 08:16 PM, Orion Poplawski wrote:
> Just recently we're seeing some very strange behavior on our system.
> Periodically we will see a sssd process start to have an ever greater number
> of connections to our ldap server until the server runs out of file
> descriptors.  This seems to be happening with a particular user, who is having
> trouble logging in at times, particularly with email (dovecot).  We see
> entries like the following on our sever:
> 
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 EXT
> oid="1.3.6.1.4.1.1466.20037" name="startTLS"
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=0 RESULT err=0 tag=120 nentries=0
> etime=0
> [05/Nov/2014:17:14:51 -0700] conn=1786153 SSL 128-bit AES
> [05/Nov/2014:17:14:51 -0700] conn=1786153 op=1 BIND
> dn="uid=user,ou=People,dc=domain,dc=com" method=128 version=3
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=2 ABANDON targetop=NOTFOUND msgid=2
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 UNBIND
> [05/Nov/2014:17:14:56 -0700] conn=1786153 op=3 fd=1022 closed - U1
> 
> I don't yet have debug info from the sssd process.  Any ideas from the above?
> 
> Restarting the sssd process seems to clear things up for a while.
> 
> - Orion
> 

I tried turning on some error log tracing to see if that helps:

[11/Nov/2014:16:33:55 -0700] - new connection on 66
[11/Nov/2014:16:33:55 -0700] - => ids_sasl_server_new (SERVER.DOMAIN.com)
[11/Nov/2014:16:33:55 -0700] - ids_sasl_getopt: plugin= option=log_level
[11/Nov/2014:16:33:55 -0700] - ids_sasl_getopt: plugin= option=auto_transition
[11/Nov/2014:16:33:55 -0700] - <= ids_sasl_server_new
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - activity on 66r
[11/Nov/2014:16:33:55 -0700] - read activity on 66
[11/Nov/2014:16:33:55 -0700] - add_pb
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - get_pb
[11/Nov/2014:16:33:55 -0700] - conn 2843 activity level = 0
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_in_use
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_in_use: 0
[11/Nov/2014:16:33:55 -0700] - do_extended
[11/Nov/2014:16:33:55 -0700] - => get_ldapmessage_controls
[11/Nov/2014:16:33:55 -0700] - <= get_ldapmessage_controls no controls
[11/Nov/2014:16:33:55 -0700] - listener got signaled
[11/Nov/2014:16:33:55 -0700] - => send_ldap_result 0::Start TLS request
accepted.Server willing to negotiate SSL.
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <= send_ldap_result
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - activity on 66r
[11/Nov/2014:16:33:55 -0700] - read activity on 66
[11/Nov/2014:16:33:55 -0700] - add_pb
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - get_pb
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit()
conn=0x9465f290, handle=8
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - do_bind
[11/Nov/2014:16:33:55 -0700] - listener got signaled
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - BIND dn="uid=USER,ou=People,dc=DOMAIN,dc=com"
method=128 version=3
[11/Nov/2014:16:33:55 -0700] - => get_ldapmessage_controls
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.2)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NOT FOUND)
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
1.3.6.1.4.1.42.2.27.8.5.1)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 1 (FOUND)
[11/Nov/2014:16:33:55 -0700] - <= get_ldapmessage_controls 1 controls
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.16)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NOT FOUND)
[11/Nov/2014:16:33:55 -0700] - do_bind: version 3 method 0x80 dn
uid=USER,ou=People,dc=DOMAIN,dc=com
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Legacy replication preoperation
plugin' #6 type 401
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster replication
preoperation plugin' #9 type 401
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.12)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NO CONTROLS)
[11/Nov/2014:16:33:55 -0700] - => slapi_control_present (looking for
2.16.840.1.113730.3.4.18)
[11/Nov/2014:16:33:55 -0700] - <= slapi_control_present 0 (NO CONTROLS)
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit() conn=0x0,
handle=6
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit() conn=0x0,
handle=5
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - => compute_limits: sizelimit=-1, timelimit=-1
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Account Usability Plugin' #1
type 403
[11/Nov/2014:16:33:55 -0700] account-usability-plugin - --> auc_pre_search
[11/Nov/2014:16:33:55 -0700] account-usability-plugin - <-- auc_pre_op
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'ACL preoperation' #2 type 403
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'deref' #4 type 403
[11/Nov/2014:16:33:55 -0700] deref-plugin - --> deref_pre_search
[11/Nov/2014:16:33:55 -0700] deref-plugin - <-- deref_pre_op
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Legacy replication preoperation
plugin' #6 type 403
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster replication
preoperation plugin' #9 type 403
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit() conn=0x0,
handle=0
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - => find_entry_internal
(dn=uid=USER,ou=people,dc=DOMAIN,dc=com) lock 0
[11/Nov/2014:16:33:55 -0700] - => dn2entry_ext
"uid=USER,ou=people,dc=DOMAIN,dc=com"
[11/Nov/2014:16:33:55 -0700] - <= dn2entry_ext 7f7d300101a0
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal_dn found
(uid=USER,ou=people,dc=DOMAIN,dc=com)
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal
[11/Nov/2014:16:33:55 -0700] - candidate list has 1 ids
[11/Nov/2014:16:33:55 -0700] id2entry - => id2entry(19)
[11/Nov/2014:16:33:55 -0700] id2entry - <= id2entry 7f7d300101a0, dn
"uid=USER,ou=people,dc=DOMAIN,dc=com" (cache)
[11/Nov/2014:16:33:55 -0700] id2entry - <= id2entry( 19 ) 7f7d300101a0 (disk)
[11/Nov/2014:16:33:55 -0700] - => send_ldap_search_entry
(uid=USER,ou=People,dc=DOMAIN,dc=com)
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Account Usability Plugin' #1
type 410
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'deref' #4 type 410
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Legacy replication preoperation
plugin' #6 type 410
[11/Nov/2014:16:33:55 -0700] - <= send_ldap_search_entry
[11/Nov/2014:16:33:55 -0700] - => send_ldap_result 0::
[11/Nov/2014:16:33:55 -0700] - <= send_ldap_result
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_vattr_get
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_getref
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_getref
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_query_attr
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_find_attr
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_find_attr
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_query_attr
[11/Nov/2014:16:33:55 -0700] - --> cos_cache_release
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_release
[11/Nov/2014:16:33:55 -0700] - <-- cos_cache_vattr_get
[11/Nov/2014:16:33:55 -0700] - => find_entry_internal
(dn=uid=USER,ou=People,dc=DOMAIN,dc=com) lock 0
[11/Nov/2014:16:33:55 -0700] - => dn2entry_ext
"uid=USER,ou=People,dc=DOMAIN,dc=com"
[11/Nov/2014:16:33:55 -0700] - <= dn2entry_ext 7f7d300101a0
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal_dn found
(uid=USER,ou=People,dc=DOMAIN,dc=com)
[11/Nov/2014:16:33:55 -0700] - <= find_entry_internal
[11/Nov/2014:16:33:55 -0700] - => slapi_pw_find value: "PASSWORD"
[11/Nov/2014:16:33:55 -0700] - <= slapi_pw_find matched "PASSWORD_HASH" using
scheme "SSHA"
[11/Nov/2014:16:33:55 -0700] - => reslimit_update_from_entry()
conn=0x9465f290, entry=0x48011630
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 0 (based on nsLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 1 (based on nsIDListScanLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 2 (based on nsPagedLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 3 (based on nsPagedIDListScanLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 4 (based on nsRangeSearchLookThroughLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 5 (based on nsSizeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 6 (based on nsTimeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 7 (based on nsPagedSizeLimit)
[11/Nov/2014:16:33:55 -0700] - reslimit_update_from_entry(): setting limit for
handle 8 (based on nsIdleTimeout)
[11/Nov/2014:16:33:55 -0700] - <= reslimit_update_from_entry() returning status 0
[11/Nov/2014:16:33:55 -0700] - => slapi_reslimit_get_integer_limit()
conn=0x9465f290, handle=8
[11/Nov/2014:16:33:55 -0700] - <= slapi_reslimit_get_integer_limit() returning
NO VALUE
[11/Nov/2014:16:33:55 -0700] - =>
slapi_pwpolicy_make_response_control[11/Nov/2014:16:33:55 -0700] - <=
slapi_pwpolicy_make_response_control[11/Nov/2014:16:33:55 -0700] - =>
slapi_add_pwd_control
[11/Nov/2014:16:33:55 -0700] - Calling plugin 'Multimaster replication
postoperation plugin' #5 type 501
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:55 -0700] - --> pagedresults_is_timedout
[11/Nov/2014:16:33:55 -0700] - <-- pagedresults_is_timedout: -
[11/Nov/2014:16:33:56 -0700] - conn 2836 leaving turbo mode due to 4
[11/Nov/2014:16:33:56 -0700] - listener got signaled

sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[find_password_expiration_attributes] (0x4000): No password policy requested.
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[simple_bind_send] (0x0100): Executing simple bind as:
uid=USER,ou=People,dc=DOMAIN,dc=com
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[simple_bind_send] (0x2000): ldap simple bind sent, msgid = 2
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[sdap_process_result] (0x2000): Trace: sh[0x7f9292dfc200], connected[1],
ops[0x7f9292dff790], ldap[0x7f9292dfad00]
sssd_default.log:(Tue Nov 11 16:33:55 2014) [sssd[be[default]]]
[sdap_process_result] (0x2000): Trace: ldap_result found nothing!
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_dispatch] (0x4000): dbus conn: 0x7f9292cf6f80
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_dispatch] (0x4000): Dispatching.
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_message_handler] (0x4000): Received SBUS method [ping]
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit
sssd_default.log:(Tue Nov 11 16:33:56 2014) [sssd[be[default]]]
[sbus_handler_got_caller_id] (0x4000): Received SBUS method [ping]

and sssd keeps making new connections:

(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [get_port_status] (0x1000):
Port status of port 389 for server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x1000): Saving the first resolved server
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x0200): Found address for server ldap.cora.DOMAIN.com: [10.10.10.1] TTL 21600
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_uri_callback] (0x0400):
Constructed uri 'ldap://ldap.cora.DOMAIN.com/'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x4000):
Using file descriptor [22] for LDAP connection.
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x0400):
Setting 6 seconds timeout for connecting
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]]
[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to
[ldap://ldap.cora.DOMAIN.com:389/??base] with fd [22].
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_sys_connect_done]
(0x0100): Executing START TLS
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292d286d0], connected[1], ops[0x7f9292dfb250], ldap[0x7f9292de3290]
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_EXTENDED]
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_connect_done] (0x0080):
START TLS result: Success(0), Start TLS request accepted.Server willing to
negotiate SSL.
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 389 of server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [fo_set_port_status] (0x0400):
Marking port 389 of duplicate server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_callback": 0x7f9292e3e8a0
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_timeout": 0x7f9292e3e9d0
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Running timer
event 0x7f9292e3e8a0 "ltdb_callback"
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Destroying
timer event 0x7f9292e3e9d0 "ltdb_timeout"
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [ldb] (0x4000): Ending timer
event 0x7f9292e3e8a0 "ltdb_callback"
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]]
[find_password_expiration_attributes] (0x4000): No password policy requested.
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=USER,ou=People,dc=DOMAIN,dc=com
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [simple_bind_send] (0x2000):
ldap simple bind sent, msgid = 2
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292d286d0], connected[1], ops[0x7f9292df92a0], ldap[0x7f9292de3290]
(Tue Nov 11 16:34:00 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: ldap_result found nothing!
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [fo_resolve_service_send]
(0x0100): Trying to resolve service 'LDAP'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [get_port_status] (0x1000):
Port status of port 389 for server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]]
[fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 6 seconds
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [get_server_status] (0x1000):
Status of server 'ldap.cora.DOMAIN.com' is 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x1000): Saving the first resolved server
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [be_resolve_server_process]
(0x0200): Found address for server ldap.cora.DOMAIN.com: [10.10.10.1] TTL 21600
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_uri_callback] (0x0400):
Constructed uri 'ldap://ldap.cora.DOMAIN.com/'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x4000):
Using file descriptor [23] for LDAP connection.
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sss_ldap_init_send] (0x0400):
Setting 6 seconds timeout for connecting
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]]
[sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to
[ldap://ldap.cora.DOMAIN.com:389/??base] with fd [23].
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_sys_connect_done]
(0x0100): Executing START TLS
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292dfbed0], connected[1], ops[0x7f9292e38950], ldap[0x7f9292dff310]
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_message]
(0x4000): Message type: [LDAP_RES_EXTENDED]
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_connect_done] (0x0080):
START TLS result: Success(0), Start TLS request accepted.Server willing to
negotiate SSL.
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [fo_set_port_status] (0x0100):
Marking port 389 of server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [set_server_common_status]
(0x0100): Marking server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [fo_set_port_status] (0x0400):
Marking port 389 of duplicate server 'ldap.cora.DOMAIN.com' as 'working'
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_callback": 0x7f9292e6ae30
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Added timed
event "ltdb_timeout": 0x7f9292e6aef0
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Running timer
event 0x7f9292e6ae30 "ltdb_callback"
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Destroying
timer event 0x7f9292e6aef0 "ltdb_timeout"
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [ldb] (0x4000): Ending timer
event 0x7f9292e6ae30 "ltdb_callback"
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]]
[find_password_expiration_attributes] (0x4000): No password policy requested.
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [simple_bind_send] (0x0100):
Executing simple bind as: uid=USER,ou=People,dc=DOMAIN,dc=com
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [simple_bind_send] (0x2000):
ldap simple bind sent, msgid = 2
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: sh[0x7f9292dfbed0], connected[1], ops[0x7f9292d26dd0], ldap[0x7f9292dff310]
(Tue Nov 11 16:34:05 2014) [sssd[be[default]]] [sdap_process_result] (0x2000):
Trace: ldap_result found nothing!
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000): dbus
conn: 0x7f9292cf6f80
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_dispatch] (0x4000):
Dispatching.
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_message_handler]
(0x4000): Received SBUS method [ping]
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_get_sender_id_send]
(0x2000): Not a sysbus message, quit
(Tue Nov 11 16:34:06 2014) [sssd[be[default]]] [sbus_handler_got_caller_id]
(0x4000): Received SBUS method [ping]

-- 
Orion Poplawski
Technical Manager                     303-415-9701 x222
NWRA, Boulder/CoRA Office             FAX: 303-415-9702
3380 Mitchell Lane                       orion at nwra.com
Boulder, CO 80301                   http://www.nwra.com