[SSSD] can't connect to openldap using GSSAPI

Alexander Gordeev lasaine at lvk.cs.msu.su
Wed Jun 23 22:43:49 UTC 2010


В Wed, 23 Jun 2010 20:57:10 +0400
Alexander Gordeev <lasaine at lvk.cs.msu.su> пишет:

> On Wed, 23 Jun 2010 16:33:17 +0200
> Sumit Bose <sbose at redhat.com> wrote:
> 
> > This message is generated if there is not matching SASL mech entry
> > ('gssapi' in your case) in the 'supportedSASLMechanisms' of the
> > rootdse. Can you check if your client can read the rootdse and if
> > you can find the gssapi entry there?
> 
> Thanks, I think I've found out what's going on!
> 
[snip]
> 
> I've looked at the code and found that sssd doesn't add any explicit
> attribute requests indeed, so I made a quick patch, which I'll post in
> reply to this letter. Please note that I haven't tested it yet, will
> do that later.

I've just tested the patch and it works. I only had to add const
qualifier to eliminate warning. But while getting supported SASL
mechanisms works good now I'm stuck with the next issue: GSSAPI auth
fails. Here is the log:

(Wed Jun 23 22:56:00 2010) [sssd[nss]] [get_client_cred] (9): Client creds: euid[0] egid[0] pid[26869].
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [accept_fd_handler] (4): Client connected!
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sss_cmd_get_version] (5): Received client version [1].
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sss_cmd_get_version] (5): Offered version [1].
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [nss_cmd_getpwnam] (4): Requesting info for [alex] from [<ALL>]
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [nss_cmd_getpwnam] (4): Requesting info for [alex at GNET]
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sss_dp_send_acct_req_create] (4): Sending request for [GNET][4097][1][name=alex]
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sbus_add_timeout] (8): 0x8098568
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sbus_dispatch] (9): dbus conn: 80A6660
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sbus_dispatch] (9): Dispatching.
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sbus_message_handler] (9): Received SBUS method [getAccountInfo]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [be_get_account_info] (4): Got request for [4097][1][name=alex]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [fo_resolve_service_send] (4): Trying to resolve service 'LDAP'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [get_server_status] (7): Status of server 'authvm.gnet' is 'name not resolved'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [get_port_status] (7): Port status of port 389 for server 'authvm.gnet' is 'neutral'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [get_server_status] (7): Status of server 'authvm.gnet' is 'name not resolved'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [resolv_gethostbyname_send] (4): Trying to resolve A record of 'authvm.gnet'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [schedule_timeout_watcher] (9): Scheduling DNS timeout watcher
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [set_server_common_status] (4): Marking server 'authvm.gnet' as 'resolving name'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [unschedule_timeout_watcher] (9): Unscheduling DNS timeout watcher
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [set_server_common_status] (4): Marking server 'authvm.gnet' as 'name resolved'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [be_resolve_server_done] (4): Found address for server authvm.gnet: [192.168.0.14]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_uri_callback] (6): Constructed uri 'ldap://authvm.gnet'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_rootdse_send] (9): Getting rootdse
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_generic_send] (6): calling ldap_search_ext with [(objectclass=*)][].
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_generic_send] (7): Requesting attrs: [supportedSASLMechanisms]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_ldap_connect_callback_add] (9): New LDAP connection to [ldap://authvm.gnet:389] with fd [19].
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_generic_send] (8): ldap_search_ext called, msgid = 1
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_process_result] (8): Trace: sh[0x80acff8], connected[1], ops[0x80b6b30], ldap[0x80ad010]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_parse_entry] (9): OriginalDN: [].
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_process_result] (8): Trace: sh[0x80acff8], connected[1], ops[0x80b6b30], ldap[0x80ad010]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_generic_done] (6): Search result: Success(0), (null)
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_rootdse_done] (9): Got rootdse
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_kinit_send] (6): Attempting kinit ((null), host/desktopvm.gnet at GNET, GNET, 86400)
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [create_tgt_req_send_buffer] (7): buffer size: 44
(Wed Jun 23 22:56:00 2010) [sssd] [main] (7): ldap_child started.
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [child_handler_setup] (8): Setting up signal handler up for pid [26870]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [child_handler_setup] (8): Signal handler set up for pid [26870]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [set_tgt_child_timeout] (6): Setting 6 seconds timeout for tgt child
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_process_result] (8): Trace: sh[0x80acff8], connected[1], ops[(nil)], ldap[0x80ad010]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_process_result] (8): Trace: ldap_result found nothing!
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [write_pipe_handler] (6): All data has been sent!
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): total buffer size: 44
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): realm_str size: 4
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): got realm_str: GNET
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): princ_str size: 24
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): got princ_str: host/desktopvm.gnet at GNET
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): keytab_name size: 0
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [unpack_buffer] (7): lifetime: 86400
(Wed Jun 23 22:56:00 2010) [[sssd[ldap_child[26870]]]] [ldap_child_get_tgt_sync] (4): Principal name is: [host/desktopvm.gnet at GNET]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [child_sig_handler] (7): Waiting for child [26870].
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [child_sig_handler] (4): child [26870] finished successfully.
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [read_pipe_handler] (6): EOF received, client finished
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_get_tgt_recv] (6): Child responded: 0 [FILE:/var/lib/sss/db/ccache_GNET]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sasl_bind_send] (4): Executing sasl bind mech: gssapi, user: host/desktopvm.gnet at GNET
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sasl_bind_send] (1): ldap_sasl_bind failed (50)[Insufficient access]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [fo_set_port_status] (4): Marking port 389 of server 'authvm.gnet' as 'not working'
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_handle_release] (8): Trace: sh[0x80acff8], connected[1], ops[(nil)], ldap[0x80ad010], destructor_lock[0], release_memory[0]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [remove_connection_callback] (9): Successfully removed connection callback.
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_check_gssapi_reconnect] (7): Client principal name is: [host/desktopvm.gnet at GNET]
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [sdap_check_gssapi_reconnect] (7): TGT end time [1277355360].
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [be_mark_offline] (8): Going offline!
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [be_run_offline_cb] (3): Going offline. Running callbacks.
(Wed Jun 23 22:56:00 2010) [sssd[be[GNET]]] [acctinfo_callback] (4): (Wed Jun 23 22:56:00 2010) [sssd[nss]] [sbus_remove_timeout] (8): 0x8098568
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sbus_dispatch] (9): dbus conn: 80994F8
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sbus_dispatch] (9): Dispatching.
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [sss_dp_get_reply] (4): Got reply (1, 5, User lookup failed) from Data Provider
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [nss_cmd_getpwnam_dp_callback] (2): Unable to get information from Data Provider
Error: 1, 5, User lookup failed
Will try to return what we have in cache
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [nss_cmd_getpwnam_callback] (2): No matching domain found for [alex], fail!
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [nss_cmd_getpwnam_callback] (2): No results for getpwnam call
Request processed. Returned 1,5,User lookup failed
(Wed Jun 23 22:56:00 2010) [sssd[nss]] [client_recv] (5): Client disconnected!
(Wed Jun 23 22:56:01 2010) [sssd[be[GNET]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kdcinfo.GNET], [2][No such file or directory]
(Wed Jun 23 22:56:01 2010) [sssd[be[GNET]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kpasswdinfo.GNET], [2][No such file or directory]
(Wed Jun 23 22:56:02 2010) [sssd[be[GNET]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kdcinfo.GNET], [2][No such file or directory]
(Wed Jun 23 22:56:02 2010) [sssd[be[GNET]]] [remove_krb5_info_files] (5): Could not remove [/var/lib/sss/pubconf/kpasswdinfo.GNET], [2][No such file or directory]

Do you see anything strange in the logs?

-- 
  Alexander
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 490 bytes
Desc: not available
URL: <https://lists.fedorahosted.org/pipermail/sssd-devel/attachments/20100624/683b67e4/attachment.sig>


More information about the sssd-devel mailing list