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.com>wrote:
> > > 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

Thanks
     Marco