I'm using sssd with pam, OpenLDAP and OpenLDAP proxy to Active Directory in a sub-domain (sj)
[root@ldap ~]# sssd --version 1.11.6
sssd.conf(sj) => slapd.conf(sj) => AD-sj
and noticing a message in the sssd logs:
[sssd[be[LDAP]]] [sbus_dispatch] (0x0080): Connection is not open for dispatching
Shown in the log: (servers are in the sub-domain sj)
ORIG - sssd.sj point to ldap.sj and AD-sj ================================================ (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_resolve_server_process] (0x0200): Found address for server ad-sj.ad.example.com: [10.47.100.15] TTL 7200 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ad-sj.ad.example.com' (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sss_ldap_init_send] (0x4000): Using file descriptor [18] for LDAP connection. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xab3a60/0xab2010 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xab3a60/0xab3cf0 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0xac0d30 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x0080): Connection is not open for dispatching. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_client_destructor] (0x0400): Removed SUDO client (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xac5610/0xac4650 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xac5610/0xac4600 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0xac5090 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x0080): Connection is not open for dispatching. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_client_destructor] (0x0400): Removed PAM client (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ad-sj.ad.example.com:636/??base] with fd [18]. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][]. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_ptask_destructor] (0x0400): Terminating periodic task [Cleanup of LDAP] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_handle_release] (0x2000): Trace: sh[0xad5450], connected[1], ops[(nil)], ldap[0xac5780], destructor_lock[0], release_memory[0] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xab6360/0xa9da20
***This appears to be preventing additional ldap search requests to Active Directory for user information to be running as the logs basically stop. ***Unclear of what 'sbus_dispatch' is using to request information and if the requests are getting to the Active Directory server and/or the requests back from the Active Directory server are blocked or something else???
***Are there any ports or network info that sbus_dispatch is using that may be blocked or something with issues across sub-domains???
The AD-sj(primary) and AD-va(secondary) are in their own sub-domain(ad) and replicate each other.
Next, I pointed sssd.conf file from the above sub-domain(sj) to another OpenLDAP server in a different sub domain(va) along with a different Active Directory server in the same sub domain(va) and seeing this in the logs which appears to be correct and not seeing the error message "Connection is not open for dispatching" but instead below seeing "Dispatching" which is allowing ldap search requests to be running against Active Directory.
sssd.conf(sj) => slapd.conf(sj) => AD-va
test 1 - sssd.sj point to ldap.va and ad-va (pointing sssd in the sj sub-domain to the va sub-domain) ============================================================== (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0x873c70 (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0x877680 (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_message_handler] (0x4000): Received SBUS method [RegisterService] (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_handler_got_caller_id] (0x4000): Received SBUS method [RegisterService] (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [client_registration] (0x0100): Cancel DP ID timeout [0x877fa0] (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [client_registration] (0x0100): Added Frontend client [SUDO] (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0x877680 (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): Dispatching. (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_message_handler] (0x4000): Received SBUS method [getDomains] (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_get_sender_id_send] (0x2000): Not a sysbus message, quit (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_handler_got_caller_id] (0x4000): Received SBUS method [getDomains] (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [be_get_subdomains] (0x2000): Undefined backend target. (Tue Apr 21 06:31:44 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0x877680 (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ad-va.ad.example.com:636/??base] with fd [16]. (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][]. (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x86ef80], connected[1], ops[0x92ee20], ldap[0x8722d0] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_entry] (0x4000): OriginalDN: []. (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [currentTime] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [subschemaSubentry] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [dsServiceName] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [namingContexts] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [defaultNamingContext] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [schemaNamingContext] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [configurationNamingContext] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [rootDomainNamingContext] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedControl] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPVersion] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedLDAPPolicies] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [highestCommittedUSN] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedSASLMechanisms] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [dnsHostName] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [ldapServiceName] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [serverName] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedCapabilities] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [isSynchronized] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [isGlobalCatalogReady] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [supportedExtension] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainFunctionality] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [forestFunctionality] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_parse_range] (0x2000): No sub-attributes for [domainControllerFunctionality] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x86ef80], connected[1], ops[0x92ee20], ldap[0x8722d0] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set (Tue Apr 21 06:31:45 2015) [sssd[be[LDAP]]] [sdap_get_rootdse_done] (0x2000): Got rootdse
On Tue, Apr 21, 2015 at 03:26:05PM +0000, Sterling Sahaydak wrote:
I'm using sssd with pam, OpenLDAP and OpenLDAP proxy to Active Directory in a sub-domain (sj)
[root@ldap ~]# sssd --version 1.11.6
sssd.conf(sj) => slapd.conf(sj) => AD-sj
and noticing a message in the sssd logs:
[sssd[be[LDAP]]] [sbus_dispatch] (0x0080): Connection is not open for dispatching
Shown in the log: (servers are in the sub-domain sj)
ORIG - sssd.sj point to ldap.sj and AD-sj
(Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_resolve_server_process] (0x0200): Found address for server ad-sj.ad.example.com: [10.47.100.15] TTL 7200 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_uri_callback] (0x0400): Constructed uri 'ldaps://ad-sj.ad.example.com' (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sss_ldap_init_send] (0x4000): Using file descriptor [18] for LDAP connection. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sss_ldap_init_send] (0x0400): Setting 6 seconds timeout for connecting (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xab3a60/0xab2010 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xab3a60/0xab3cf0 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0xac0d30 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x0080): Connection is not open for dispatching. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_client_destructor] (0x0400): Removed SUDO client (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xac5610/0xac4650 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xac5610/0xac4600 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 0xac5090 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_dispatch] (0x0080): Connection is not open for dispatching. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_client_destructor] (0x0400): Removed PAM client (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to [ldaps://ad-sj.ad.example.com:636/??base] with fd [18].
So in the diagram above you indicated that sssd is talking not to ad-sj, but to an OpenLDAP proxy. But the logs shows a connection attempt to ad-sj. That seems confusing to me..
(Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_rootdse_send] (0x4000): Getting rootdse (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(objectclass=*)][]. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [namingContexts] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedControl] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedExtension] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedFeatures] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedLDAPVersion] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [supportedSASLMechanisms] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [domainControllerFunctionality] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [defaultNamingContext] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [highestCommittedUSN] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 1 (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_id_op_destroy] (0x4000): releasing operation connection (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [be_ptask_destructor] (0x0400): Terminating periodic task [Cleanup of LDAP] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sdap_handle_release] (0x2000): Trace: sh[0xad5450], connected[1], ops[(nil)], ldap[0xac5780], destructor_lock[0], release_memory[0] (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [remove_connection_callback] (0x4000): Successfully removed connection callback. (Tue Apr 21 05:46:27 2015) [sssd[be[LDAP]]] [sbus_remove_watch] (0x2000): 0xab6360/0xa9da20
***This appears to be preventing additional ldap search requests to Active Directory for user information to be running as the logs basically stop.
Even the pings?
I am really only guessing, but what SSSD tried to request was the rootDSE record. Is it readable and available on your server?
***Unclear of what 'sbus_dispatch' is using to request information and if the requests are getting to the Active Directory server and/or the requests back from the Active Directory server are blocked or something else???
sbus is a local communication over a local UNIX socket, between the different SSSD components. Nothing to do with network communication.
sssd-users@lists.fedorahosted.org
-
Jakub Hrozek -
Sterling Sahaydak