В Wed, 23 Jun 2010 20:57:10 +0400
Alexander Gordeev <lasaine(a)lvk.cs.msu.su> пишет:
On Wed, 23 Jun 2010 16:33:17 +0200
Sumit Bose <sbose(a)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@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@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@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@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@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@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