On Tue, 2012-02-07 at 16:12 +0100, Marco Pizzoli wrote:
On Tue, Feb 7, 2012 at 2:41 PM, Stephen Gallagher sgallagh@redhat.com wrote: On Tue, 2012-02-07 at 14:32 +0100, Jan Zelený wrote: > > On Tue, Feb 7, 2012 at 2:10 PM, Stephen Gallagher > sgallagh@redhat.comwrote: > > > On Tue, 2012-02-07 at 14:04 +0100, Marco Pizzoli wrote: > > > > Hi guys, > > > > Again I need your help... I'm using and I configured a > > > > domain/my_ldap. During the startup I see these logs: > > > > > > > > [cut] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_op_connect_step] (0x4000): beginning to connect > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [get_server_status] > > > > (0x1000): Status of server 'ldap01.dont.mind.it' is 'name not > > > > resolved' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [get_port_status] > > > > (0x1000): Port status of port 389 for server 'ldap01.dont.mind.it' is > > > > 'neutral' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to > > > > 5 seconds > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [get_server_status] > > > > (0x1000): Status of server 'ldap01.dont.mind.it' is 'name not > > > > resolved' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [resolv_is_address] > > > > (0x4000): [ldap01.dont.mind.it] does not look like an IP address > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [resolv_gethostbyname_step] (0x2000): Querying files > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [resolv_gethostbyname_files_send] (0x0100): Trying to resolve A record > > > > of 'ldap01.dont.mind.it' in files > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [set_server_common_status] (0x0100): Marking server > > > > 'ldap01.dont.mind.it' as 'resolving name' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [set_server_common_status] (0x0100): Marking server > > > > 'ldap01.dont.mind.it' as 'name resolved' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [be_resolve_server_done] (0x0100): Found address for server > > > > ldap01.dont.mind.it: [192.168.146.128] TTL 7200 > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_uri_callback] > > > > (0x0400): Constructed uri 'ldap://ldap01.dont.mind.it:389' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sss_ldap_init_send] > > > > (0x4000): Using file descriptor [24] for LDAP connection. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sss_ldap_init_send] > > > > (0x0400): Setting 6 seconds timeout for connecting > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_ldap_connect_callback_add] (0x1000): New LDAP connection to > > > > [ldap://ldap01.dont.mind.it:389/??base] with fd [24]. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_get_rootdse_send] > > > > (0x4000): Getting rootdse > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with > > > > [(objectclass=*)][]. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [*] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [altServer] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [namingContexts] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [supportedControl] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [supportedExtension] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [supportedFeatures] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [supportedLDAPVersion] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [supportedSASLMechanisms] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [defaultNamingContext] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [lastUSN] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x1000): Requesting attrs: > > > > [highestCommittedUSN] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = > > > > 1 > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_process_result] > > > > (0x2000): Trace: sh[0x7f6ec4b54440], connected[1], > > > > ops[0x7f6ec4b6a610], ldap[0x7f6ec4b579c0] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_process_message] > > > > (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_parse_entry] > > > > (0x4000): OriginalDN: []. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_process_result] > > > > (0x2000): Trace: sh[0x7f6ec4b54440], connected[1], > > > > ops[0x7f6ec4b6a610], ldap[0x7f6ec4b579c0] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_process_message] > > > > (0x4000): Message type: [LDAP_RES_SEARCH_RESULT] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no > > > > errmsg set > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_get_rootdse_done] > > > > (0x4000): Got rootdse > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [get_naming_context] > > > > (0x0200): Using value from [namingContexts] as naming context. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_set_search_base] > > > > (0x0100): Setting option [ldap_sudo_search_base] to > > > > [dc=dont,dc=mind.it]. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_parse_search_base] (0x0100): Search base added: > > > > [SUDO][dc=dont.mind.it][SUBTREE][] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_server_opts_from_rootdse] (0x0200): No known USN scheme is > > > > supported by this server! > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_get_server_opts_from_rootdse] (0x0200): Will use modification > > > > timestamp as usn! > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [fo_set_port_status] > > > > (0x0100): Marking port 389 of server 'ldap01.dont.mind.it' as 'not > > > > working' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_handle_release] > > > > (0x2000): Trace: sh[0x7f6ec4b54440], connected[1], ops[(nil)], > > > > ldap[0x7f6ec4b579c0], destructor_lock[0], release_memory[0] > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [remove_connection_callback] (0x4000): Successfully removed connection > > > > callback. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_op_connect_done] (0x0010): Authentication mechanism not > > > > Supported by server > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_op_connect_done] (0x4000): attempting failover retry on op #1 > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_op_connect_step] (0x4000): beginning to connect > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [fo_resolve_service_send] (0x0100): Trying to resolve service 'LDAP' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [get_server_status] > > > > (0x1000): Status of server 'ldap01.dont.mind.it' is 'name resolved' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [get_port_status] > > > > (0x1000): Port status of port 389 for server 'ldap01.dont.mind.it' is > > > > 'not working' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [fo_resolve_service_send] (0x0020): No available servers for service > > > > 'LDAP' > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_release_conn_data] (0x4000): releasing unused connection > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_op_connect_done] (0x0020): Failed to connect, going offline > > > > (5 [Input/output error]) > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [be_mark_offline] > > > > (0x2000): Going offline! > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [be_run_offline_cb] > > > > (0x0080): Going offline. Running callbacks. > > > > (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] > > > > [sdap_id_op_connect_done] (0x4000): notify offline to op #1 > > > > [cut] > > > > > > > > My LDAP server is OpenLDAP. and I have configured the tls part. > > > > > > > > [root@fedora16 ~]# netstat -ntlp |grep slapd > > > > tcp 0 0 0.0.0.0:636 0.0.0.0:* > > > > LISTEN 2951/slapd > > > > tcp 0 0 0.0.0.0:389 0.0.0.0:* > > > > LISTEN 2951/slapd > > > > tcp 0 0 :::636 :::* > > > > LISTEN 2951/slapd > > > > tcp 0 0 :::389 :::* > > > > LISTEN 2951/slapd > > > > > > > > This is the interesting part of my domain/my_ldap section of sssd.conf > > > > > > > > [domain/my_ldap] > > > > description = LDAP Users domain > > > > min_id = 7000 > > > > max_id = 8000 > > > > timeout = 10 > > > > enumerate = TRUE > > > > entry_cache_timeout = 5400 > > > > cache_credentials = TRUE > > > > account_cache_expiration = 0 > > > > id_provider = ldap > > > > use_fully_qualified_names = FALSE > > > > auth_provider = ldap > > > > access_provider = permit > > > > chpass_provider = ldap > > > > lookup_family_order = ipv4_first > > > > dns_resolver_timeout = 5 > > > > #dns_discovery_domain = > > > > #override_gid = > > > > case_sensitive = True > > > > > > > > ldap_uri = ldap://ldap01.dont.mind.it:389 > > > > ldap_chpass_uri = ldap://ldap01.dont.mind.it:389 > > > > ldap_search_base = > > > > dc=dont,dc=mind.it?sub?(objectClass=inetOrgPerson)<http://mind.it?sub? > > > > %28objectClass=inetOrgPerson%29> ldap_schema = rfc2307bis > > > > ldap_default_bind_dn = cn=mydn,dc=dont,dc=mind.it > > > > ldap_default_authtok_type = pippo > > > > #ldap_default_authtok > > > > ldap_user_object_class = posixAccount > > > > ldap_user_name = uid > > > > ldap_user_uid_number = uidNumber > > > > ldap_user_gid_number = gidNumber > > > > ldap_user_gecos = gecos > > > > ldap_user_home_directory = homeDirectory > > > > ldap_user_shell = loginShell > > > > ldap_user_uuid = entryUUID > > > > ldap_user_modify_timestamp = modifyTimestamp > > > > ldap_user_shadow_last_change = shadowLastChange > > > > ldap_user_shadow_min = shadowMin > > > > > > > > #### INIZIO - SSL/TLS #### > > > > # > > > > # Imposto la richiesta e la validazione del certificato > > > > ldap_tls_reqcert = demand > > > > # > > > > #ldap_tls_cacert = > > > > ldap_tls_cacertdir = /etc/pki/tls/certs > > > > #ldap_tls_cert = > > > > #ldap_tls_key = > > > > #ldap_tls_cipher_suite = > > > > ldap_id_use_start_tls = false > > > > #### FINE - SSL/TLS #### > > > > > > > > Could you help me in understanding what is the cause of the backend > > > > discard? > > > > > > Can you tell us if it works if you do: > > > > > > ldapsearch -H ldap://ldap.dont.mind.it -x -w \ > > > -D cn=mydn,dc=dont,dc=mind.it -b dc=dont,dc=mind.it \ > > > objectClass=inetOrgPerson > > > > Hi, yes it works. Obviously I posted a camoufled binddn, basedn, etc... > > I think you should also try the command with -ZZ argument to test if TLS > initialization isn't getting in your way. Also please check that > /etc/pki/tls/certs contains hashes (symlinks) of certificates you wish to use. > > > > > By executing your ldapsearch I obtain this: > > [cut] > > # search result > > search: 2 > > result: 0 Success > > > > # numResponses: 164 > > # numEntries: 163 > > > > I already checked by tcpdump-ing the dialog between sssd and the ldap > > server and I saw only one ldapsearch executed, and this was simply against > > the rootDSE. I expected to see another one against my user db / basedn.
The only way that (Tue Feb 7 13:44:04 2012) [sssd[be[my_ldap]]] [sdap_id_op_connect_done] (0x0010): Authentication mechanism not Supported by server is possible is if we get ENOTSUP back from the connection attempt. This can only happen if: if (state->do_auth && sasl_mech && state->use_rootdse) { if (!sdap_is_sasl_mech_supported(state->sh, sasl_mech)) { tevent_req_error(req, ENOTSUP); return; } } So that sounds to me like the list of supportedSASLMechanisms in the RootDSE is wrong. Marco, please try this: ldapsearch -H ldap://ldap.dont.mind.it -x -b '' -s base \ supportedSASLMechanisms And tell us what it says. If that option returns nothing, I think that's probably a misconfiguration on the server (such as not having this attribute be readable by anonymous users). That said, we should probably assume by default that SASL/SIMPLE is always supported, even if the server is being stupid.
Here it is:
[root@fedora16 ~]# ldapsearch -v -x -h 127.0.0.1 -b "" -s base -D "cn=Manager,dc=dont,dc=mind.it" -wmy_pw supportedSASLMechanisms ldap_initialize( ldap://127.0.0.1 ) filter: (objectclass=*) requesting: supportedSASLMechanisms # extended LDIF # # LDAPv3 # base <> with scope baseObject # filter: (objectclass=*) # requesting: supportedSASLMechanisms #
# dn: supportedSASLMechanisms: GSSAPI
# search result search: 2 result: 0 Success
# numResponses: 2 # numEntries: 1
According to that, your LDAP server doesn't support any authentication except GSSAPI (probably Kerberos). Obviously ldapsearch still works, so it looks to me like the LDAP server isn't properly reporting what it reports.
Please open a bug. SSSD should be assuming that we always support SIMPLE.