On Tue, 2012-02-07 at 16:12 +0100, Marco Pizzoli wrote:
On Tue, Feb 7, 2012 at 2:41 PM, Stephen Gallagher
<sgallagh(a)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(a)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
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.