Hi folks,
Any help here would be appreciated, I don't seem to see what the issue is. I can login using kinit just fine, but sssd fails when using ssh. It seems like it has something to do with the files in /var/lib/sss/pubconf going missing, which causes sssd-krb5 to fail with: Cannot find KDC for requested realm.
This is CentOS 6, sssd-1.8.0-32.el6.x86_64.
e.g. kinit logins works: [testuser@test01 ~]$ kinit Password for testuser@MYREALM.COM: Warning: Your password will expire in 41 days on Sun Mar 10 19:01:44 2013 [testuser@test01 ~]$ klist Ticket cache: FILE:/tmp/krb5cc_501 Default principal: testuser@MYREALM.COM
Valid starting Expires Service principal 01/27/13 22:13:00 01/28/13 08:13:00 krbtgt/MYREALM.COM@MYREALM.COM renew until 02/03/13 22:12:53 [testuser@test01 ~]$
But over ssh:
/var/log/secure: Jan 27 21:57:03 test1 sshd[2882]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.74.34.39 user=testuser Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): system info: [Cannot find KDC for requested realm] Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.74.34.39 user=testuser Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): received for user testuser: 4 (System error) Jan 27 21:57:05 test1 sshd[2882]: Failed password for testuser from 10.74.34.39 port 55143 ssh2 Jan 27 21:57:11 test1 sshd[2883]: Connection closed by 10.74.34.39
sssd -i -d9 + SSSD_KRB5_LOCATOR_DEBUG=1 output: (Sun Jan 27 21:57:03 2013) [sssd[pam]] [sss_dp_req_destructor] (0x0400): Deleting request: [0x4175f0:3:testuser@MYREALM.COM] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [sdap_process_result] (0x2000): Trace: sh[0x248b180], connected[1], ops[(nil)], ldap[0x248b360] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing! (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [sbus_dispatch] (0x4000): dbus conn: 2485210 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [sbus_dispatch] (0x4000): Dispatching. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [sbus_message_handler] (0x4000): Received SBUS method [pamHandler] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [be_pam_handler] (0x0100): Got request with the following data (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): command: PAM_AUTHENTICATE (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): domain: MYREALM.COM (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): user: testuser (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): service: sshd (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): tty: ssh (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): ruser: (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): rhost: 10.74.34.39 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): authtok type: 1 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): authtok size: 12 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): newauthtok type: 0 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): newauthtok size: 0 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): priv: 1 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [pam_print_data] (0x0100): cli_pid: 2882 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [krb5_pam_handler] (0x1000): Wait queue of user [testuser] is empty, running request immediately. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [ldb] (0x4000): tevent: Added timed event "ltdb_callback": 0x2537a00 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [ldb] (0x4000): tevent: Added timed event "ltdb_timeout": 0x2539b50 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [ldb] (0x4000): tevent: Destroying timer event 0x2539b50 "ltdb_timeout" (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [ldb] (0x4000): tevent: Ending timer event 0x2537a00 "ltdb_callback" (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [krb5_auth_send] (0x0100): No ccache file for user [testuser] found. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [krb5_auth_send] (0x4000): Ccache_file is [not set] and is not active and TGT is not valid. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [fo_resolve_service_send] (0x0100): Trying to resolve service 'KERBEROS' (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [get_server_status] (0x1000): Status of server 'auth01.myrealm.com' is 'working' (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [get_port_status] (0x1000): Port status of port 88 for server 'auth01.MYREALM.COM' is 'neutral' (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [fo_resolve_service_activate_timeout] (0x2000): Resolve timeout set to 10 seconds (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [get_server_status] (0x1000): Status of server 'auth01.myrealm.com' is 'working' (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [be_resolve_server_done] (0x1000): Saving the first resolved server (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [be_resolve_server_done] (0x0200): Found address for server auth01.MYREALM.COM: [192.168.246.37] TTL 300 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [krb5_find_ccache_step] (0x4000): Recreating ccache file. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [create_ccache_dir] (0x4000): Ccache directory name [/tmp/krb5cc_501_XXXXXX] does not contain illegal patterns. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [child_handler_setup] (0x2000): Setting up signal handler up for pid [2884] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [become_user] (0x4000): Trying to become user [501][501]. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [child_handler_setup] (0x2000): Signal handler set up for pid [2884] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [write_pipe_handler] (0x0400): All data has been sent! (Sun Jan 27 21:57:03 2013) [sssd] [main] (0x1000): krb5_child started. (Sun Jan 27 21:57:03 2013) [[sssd[krb5_child[2884]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment. (Sun Jan 27 21:57:03 2013) [[sssd[krb5_child[2884]]]] [krb5_child_setup] (0x1000): Cannot read [SSSD_KRB5_LIFETIME] from environment. (Sun Jan 27 21:57:03 2013) [[sssd[krb5_child[2884]]]] [krb5_child_setup] (0x4000): Not using FAST. [sssd_krb5_locator] sssd_krb5_locator_init called [sssd_krb5_locator] open failed [2][No such file or directory]. [sssd_krb5_locator] get_krb5info failed. [sssd_krb5_locator] sssd_krb5_locator_close called [sssd_krb5_locator] sssd_krb5_locator_init called [sssd_krb5_locator] open failed [2][No such file or directory]. [sssd_krb5_locator] get_krb5info failed. [sssd_krb5_locator] sssd_krb5_locator_close called [sssd_krb5_locator] sssd_krb5_locator_init called [sssd_krb5_locator] open failed [2][No such file or directory]. [sssd_krb5_locator] get_krb5info failed. [sssd_krb5_locator] sssd_krb5_locator_close called [sssd_krb5_locator] sssd_krb5_locator_init called [sssd_krb5_locator] open failed [2][No such file or directory]. sssd_krb5_locator] open failed [2][No such file or directory]. [sssd_krb5_locator] get_krb5info failed. [sssd_krb5_locator] sssd_krb5_locator_close called (Sun Jan 27 21:57:03 2013) [[sssd[krb5_child[2884]]]] [get_and_save_tgt] (0x0020): 660: [-1765328230][Cannot find KDC for requested realm] (Sun Jan 27 21:57:03 2013) [[sssd[krb5_child[2884]]]] [tgt_req_child] (0x0020): 919: [-1765328230][Cannot find KDC for requested realm] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [read_pipe_handler] (0x0400): EOF received, client finished (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [krb5_child_done] (0x4000): child response [4][1][36]. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [check_wait_queue] (0x1000): Wait queue for user [testuser] is empty. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [be_pam_handler_callback] (0x0100): Backend returned: (0, 4, <NULL>) [Success] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [be_pam_handler_callback] (0x0100): Sending result [4][MYREALM.COM] (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [be_pam_handler_callback] (0x0100): Sent result [4][MYREALM.COM] (Sun Jan 27 21:57:03 2013) [sssd[pam]] [sbus_remove_timeout] (0x2000): 0x751c90 (Sun Jan 27 21:57:03 2013) [sssd[pam]] [sbus_dispatch] (0x4000): dbus conn: 754800 (Sun Jan 27 21:57:03 2013) [sssd[pam]] [sbus_dispatch] (0x4000): Dispatching. (Sun Jan 27 21:57:03 2013) [sssd[pam]] [pam_dp_process_reply] (0x0100): received: [4][MYREALM.COM] (Sun Jan 27 21:57:03 2013) [sssd[pam]] [pam_reply] (0x0100): pam_reply get called. (Sun Jan 27 21:57:03 2013) [sssd[pam]] [pam_reply] (0x0100): blen: 79 (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [child_sig_handler] (0x1000): Waiting for child [2884]. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [child_sig_handler] (0x0100): child [2884] finished successfully. (Sun Jan 27 21:57:03 2013) [sssd[be[MYREALM.COM]]] [sss_child_handler] (0x2000): waitpid failed [10]: No child processes
/etc/krb5.conf: [logging] default = FILE:/var/log/krb5libs.log kdc = FILE:/var/log/krb5kdc.log admin_server = FILE:/var/log/kadmind.log
[libdefaults] default_realm = MYREALM.COM dns_lookup_realm = false dns_lookup_kdc = false ticket_lifetime = 24h renew_lifetime = 7d forwardable = true
[realms] MYREALM.COM = { kdc = auth01.myrealm.com:88 admin_server = auth01.myrealm.com default_domain = myrealm.com }
[domain_realm] .myrealm.com = MYREALM.COM myrealm.com = MYREALM.COM
/etc/sssd/sssd.conf: [sssd] debug_level = 0xFFF0 config_file_version = 2 reconnection_retries = 3 sbus_timeout = 30 services = nss, pam domains = MYREALM.COM [nss] debug_level = 0xFFF0 filter_groups = root filter_users = root reconnection_retries = 3 [pam] reconnection_retries = 3 debug_level = 0xFFF0 [domain/MYREALM.COM] debug_level = 0xFFF0 min_id = 1max_id = 0 ldap_page_size = 1000 enumerate = true cache_credentials = true id_provider = ldap chpass_provider = krb5 ldap_uri = ldaps://auth01.myrealm.com:3269 ldap_search_base = dc=myrealm,dc=com ldap_user_search_base = dc=myrealm,dc=com ldap_group_search_base =dc=myrealm,dc=com ldap_schema = rfc2307bis ldap_default_bind_dn = Administrator@MYREALM.COM ldap_default_authtok = p@$$word ldap_default_authtok_type = password ldap_user_object_class = user ldap_user_name = sAMAccountName ldap_user_home_directory = unixHomeDirectory ldap_group_object_class = group ldap_user_principal = userPrincipalName ldap_user_shadow_last_change = pwdLastSet ldap_tls_reqcert = never ldap_tls_cacertdir = /etc/openldap/cacerts ldap_referrals = false auth_provider = krb5 krb5_server = auth01.myrealm.com:88 krb5_realm = MYREALM.COM krb5_changepw_principal = kadmin/changepw krb5_ccachedir = /tmp krb5_ccname_template = FILE:%d/krb5cc_%U_XXXXXX krb5_auth_timeout = 15
/etc/pam.d/password-auth: #%PAM-1.0 # This file is auto-generated. # User changes will be destroyed the next time authconfig is run. auth required pam_env.so auth sufficient pam_unix.so nullok try_first_pass auth requisite pam_succeed_if.so uid >= 500 quiet auth sufficient pam_sss.so use_first_pass auth required pam_deny.so
account required pam_unix.so account sufficient pam_localuser.so account sufficient pam_succeed_if.so uid < 500 quiet account [default=bad success=ok user_unknown=ignore] pam_sss.so account required pam_permit.so
password requisite pam_cracklib.so try_first_pass retry=3 type= password sufficient pam_unix.so sha512 shadow nullok try_first_pass use_authtok password sufficient pam_sss.so use_authtok password required pam_deny.so session optional pam_keyinit.so revoke session required pam_limits.so session [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid session required pam_unix.so session optional pam_sss.so session required pam_mkhomedir.so umask=0022 skel=/etc/skel
On Sun, Jan 27, 2013 at 02:23:03PM -0800, C. S. wrote:
Hi folks,
Any help here would be appreciated, I don't seem to see what the issue is. I can login using kinit just fine,
Right, kinit bypasses the PAM stacks and talks directly to the libkrb5 and the kdc.
but sssd fails when using ssh. It seems like it has something to do with the files in /var/lib/sss/pubconf going missing, which causes sssd-krb5 to fail with: Cannot find KDC for requested realm.
Yes, I think so too, but what puzzles me is that resolving went OK, then the kdcinfo files are written. Unfortunately there is no debug output unless there is an error, so we can't see the realm etc.. The "No such file or directory" errors indicate that the krb5info files are indeed missing.
Are there perhaps any AVC denials when the SSSD is attempting to write the kdcinfo files?
Are you sure there is no typo in the realm name? Can you also kinit on the client machine, in other words, if you were testing by ssh testuser@testhost, can you kinit on testhost? What also seems strange to me is that if krb5.conf was configured correctly on the client machine, then I would expect the krb5 child process to use the KDC info from the krb5.conf file..by the time we reach the child process, it's mostly standard krb5 library calls.
This is CentOS 6, sssd-1.8.0-32.el6.x86_64.
e.g. kinit logins works: [testuser@test01 ~]$ kinit Password for testuser@MYREALM.COM: Warning: Your password will expire in 41 days on Sun Mar 10 19:01:44 2013 [testuser@test01 ~]$ klist Ticket cache: FILE:/tmp/krb5cc_501 Default principal: testuser@MYREALM.COM
Valid starting Expires Service principal 01/27/13 22:13:00 01/28/13 08:13:00 krbtgt/MYREALM.COM@MYREALM.COM renew until 02/03/13 22:12:53 [testuser@test01 ~]$
But over ssh:
/var/log/secure: Jan 27 21:57:03 test1 sshd[2882]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.74.34.39 user=testuser Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): system info: [Cannot find KDC for requested realm] Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.74.34.39 user=testuser Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): received for user testuser: 4 (System error) Jan 27 21:57:05 test1 sshd[2882]: Failed password for testuser from 10.74.34.39 port 55143 ssh2 Jan 27 21:57:11 test1 sshd[2883]: Connection closed by 10.74.34.39
sssd -i -d9 + SSSD_KRB5_LOCATOR_DEBUG=1 output:
Thank you for providing the detailed debug logs.
Well, I had to resort adding a DEBUG() line to get_and_save_tgt() to print out the realm and princ, and it turned out there was a typo on the UPN in my Samba 4 directory entry for the user. I sort of expected it to be something stupid. On that note, do you have any suggestions on where more debugging could be added? If I have the cycles I was thinking of submitting a patch to make these issues easier to figure out.
Thanks!
cs
On Mon, Jan 28, 2013 at 2:56 AM, Jakub Hrozek jhrozek@redhat.com wrote:
On Sun, Jan 27, 2013 at 02:23:03PM -0800, C. S. wrote:
Hi folks,
Any help here would be appreciated, I don't seem to see what the issue
is.
I can login using kinit just fine,
Right, kinit bypasses the PAM stacks and talks directly to the libkrb5 and the kdc.
but sssd fails when using ssh. It seems like it has something to do with the files in /var/lib/sss/pubconf going missing, which causes sssd-krb5 to fail with: Cannot find KDC for
requested
realm.
Yes, I think so too, but what puzzles me is that resolving went OK, then the kdcinfo files are written. Unfortunately there is no debug output unless there is an error, so we can't see the realm etc.. The "No such file or directory" errors indicate that the krb5info files are indeed missing.
Are there perhaps any AVC denials when the SSSD is attempting to write the kdcinfo files?
Are you sure there is no typo in the realm name? Can you also kinit on the client machine, in other words, if you were testing by ssh testuser@testhost, can you kinit on testhost? What also seems strange to me is that if krb5.conf was configured correctly on the client machine, then I would expect the krb5 child process to use the KDC info from the krb5.conf file..by the time we reach the child process, it's mostly standard krb5 library calls.
This is CentOS 6, sssd-1.8.0-32.el6.x86_64.
e.g. kinit logins works: [testuser@test01 ~]$ kinit Password for testuser@MYREALM.COM: Warning: Your password will expire in 41 days on Sun Mar 10 19:01:44 2013 [testuser@test01 ~]$ klist Ticket cache: FILE:/tmp/krb5cc_501 Default principal: testuser@MYREALM.COM
Valid starting Expires Service principal 01/27/13 22:13:00 01/28/13 08:13:00 krbtgt/MYREALM.COM@MYREALM.COM renew until 02/03/13 22:12:53 [testuser@test01 ~]$
But over ssh:
/var/log/secure: Jan 27 21:57:03 test1 sshd[2882]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.74.34.39 user=testuser Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): system info:
[Cannot
find KDC for requested realm] Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.74.34.39 user=testuser Jan 27 21:57:03 test1 sshd[2882]: pam_sss(sshd:auth): received for user testuser: 4 (System error) Jan 27 21:57:05 test1 sshd[2882]: Failed password for testuser from 10.74.34.39 port 55143 ssh2 Jan 27 21:57:11 test1 sshd[2883]: Connection closed by 10.74.34.39
sssd -i -d9 + SSSD_KRB5_LOCATOR_DEBUG=1 output:
Thank you for providing the detailed debug logs. _______________________________________________ sssd-users mailing list sssd-users@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-users
On Mon, Jan 28, 2013 at 05:34:33PM -0800, C. S. wrote:
Well, I had to resort adding a DEBUG() line to get_and_save_tgt() to print out the realm and princ, and it turned out there was a typo on the UPN in my Samba 4 directory entry for the user. I sort of expected it to be something stupid. On that note, do you have any suggestions on where more debugging could be added? If I have the cycles I was thinking of submitting a patch to make these issues easier to figure out.
Thanks!
cs
We've actually added quite some new DEBUG messages to both the Kerberos and LDAP child processes during 1.9 development, can you check if the one you needed is perhaps already there?
http://git.fedorahosted.org/cgit/sssd.git/tree/src/providers/krb5/krb5_child...
http://git.fedorahosted.org/cgit/sssd.git/tree/src/providers/ldap/ldap_child...
If not, a patch would be welcome!
sssd-users@lists.fedorahosted.org
-
C. S. -
Jakub Hrozek