[Freeipa-users] IPA not authenticating - SSSD issue maybe

Mon Apr 15 17:12:55 UTC 2013

Hello,

>From time to time we are getting complaints that I can sum up as "I cannot
log in to server X"

Here is a spinet of the /var/log/sssd/sssd_DOMAIN.log ...

*(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler]
(0x0100): Got request with the following data
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
command: PAM_ACCT_MGMT
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
domain: 4OVER.COM
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
user: tradeftp
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
service: vsftpd
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
tty: ftp
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
ruser: tradeftp
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
rhost: mammoth.4over.com
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
authtok type: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
authtok size: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
priv: 1
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
cli_pid: 17841
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [ipa_hbac_evaluate_rules]
(0x0080): Access granted by HBAC rule [allow_all]
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler_callback]
(0x0100): Backend returned: (0, 0, <NULL>) [Success]
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler_callback]
(0x0100): Backend returned: (0, 0, Success) [Success]
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler_callback]
(0x0100): Sending result [0][4OVER.COM]
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler_callback]
(0x0100): Sent result [0][4OVER.COM]
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler] (0x0100):
Got request with the following data
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
command: PAM_SETCRED
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
domain: 4OVER.COM
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
user: tradeftp
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
service: vsftpd
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
tty: ftp
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
ruser: tradeftp
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
rhost: mammoth.4over.com
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
authtok type: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
authtok size: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
newauthtok type: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
newauthtok size: 0
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
priv: 1
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [pam_print_data] (0x0100):
cli_pid: 17841
(Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM]]] [be_pam_handler] (0x0100):
Sending result [0][4OVER.COM]
(Mon Apr 15 09:37:00 2013) [sssd[be[4OVER.COM]]] [be_get_account_info]
(0x0100): Got request for [3][1][name=tradeftp]
(Mon Apr 15 09:37:00 2013) [sssd[be[4OVER.COM]]]
[sdap_initgr_nested_search] (0x0040): Search for group
cn=ipausers,cn=groups,cn=accounts,dc=4over,dc=com, returned 0 results.
Skipping
*

Here (more interesting) is the krb log file

*(Mon Apr 15 09:36:54 2013) [[sssd[krb5_child[17855]]]] [unpack_buffer]
(0x0100): cmd [241] uid [6676] gid [104] validate [true] offline [false]
UPN [tradeftp at 4OVER.COM]
(Mon Apr 15 09:36:54 2013) [[sssd[krb5_child[17855]]]] [unpack_buffer]
(0x0100): ccname: [FILE:/tmp/krb5cc_6676_0CTKUc] keytab: [/etc/krb5.keytab]
(Mon Apr 15 09:36:54 2013) [[sssd[krb5_child[17855]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Mon Apr 15 09:36:54 2013) [[sssd[krb5_child[17855]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
(Mon Apr 15 09:36:54 2013) [[sssd[krb5_child[17855]]]]
[krb5_set_canonicalize] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Mon Apr 15 09:36:54 2013) [[sssd[krb5_child[17855]]]] [krb5_child_setup]
(0x0100): Not using FAST.
(Mon Apr 15 09:36:56 2013) [[sssd[krb5_child[17862]]]] [unpack_buffer]
(0x0100): cmd [241] uid [6676] gid [104] validate [true] offline [false]
UPN [tradeftp at 4OVER.COM]
(Mon Apr 15 09:36:56 2013) [[sssd[krb5_child[17862]]]] [unpack_buffer]
(0x0100): ccname: [FILE:/tmp/krb5cc_6676_0CTKUc] keytab: [/etc/krb5.keytab]
(Mon Apr 15 09:36:56 2013) [[sssd[krb5_child[17862]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Mon Apr 15 09:36:56 2013) [[sssd[krb5_child[17862]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
(Mon Apr 15 09:36:56 2013) [[sssd[krb5_child[17862]]]]
[krb5_set_canonicalize] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Mon Apr 15 09:36:56 2013) [[sssd[krb5_child[17862]]]] [krb5_child_setup]
(0x0100): Not using FAST.
(Mon Apr 15 09:37:00 2013) [[sssd[krb5_child[17871]]]] [unpack_buffer]
(0x0100): cmd [241] uid [6676] gid [104] validate [true] offline [false]
UPN [tradeftp at 4OVER.COM]
(Mon Apr 15 09:37:00 2013) [[sssd[krb5_child[17871]]]] [unpack_buffer]
(0x0100): ccname: [FILE:/tmp/krb5cc_6676_0CTKUc] keytab: [/etc/krb5.keytab]
(Mon Apr 15 09:37:00 2013) [[sssd[krb5_child[17871]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Mon Apr 15 09:37:00 2013) [[sssd[krb5_child[17871]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
(Mon Apr 15 09:37:00 2013) [[sssd[krb5_child[17871]]]]
[krb5_set_canonicalize] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Mon Apr 15 09:37:00 2013) [[sssd[krb5_child[17871]]]] [krb5_child_setup]
(0x0100): Not using FAST.
(Mon Apr 15 09:37:01 2013) [[sssd[krb5_child[17881]]]] [unpack_buffer]
(0x0100): cmd [241] uid [6676] gid [104] validate [true] offline [false]
UPN [tradeftp at 4OVER.COM]
(Mon Apr 15 09:37:01 2013) [[sssd[krb5_child[17881]]]] [unpack_buffer]
(0x0100): ccname: [FILE:/tmp/krb5cc_6676_NgD4RE] keytab: [/etc/krb5.keytab]
(Mon Apr 15 09:37:01 2013) [[sssd[krb5_child[17881]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_RENEWABLE_LIFETIME] from environment.
(Mon Apr 15 09:37:01 2013) [[sssd[krb5_child[17881]]]] [krb5_child_setup]
(0x0100): Cannot read [SSSD_KRB5_LIFETIME] from environment.
(Mon Apr 15 09:37:01 2013) [[sssd[krb5_child[17881]]]]
[krb5_set_canonicalize] (0x0100): SSSD_KRB5_CANONICALIZE is set to [true]
(Mon Apr 15 09:37:01 2013) [[sssd[krb5_child[17881]]]] [krb5_child_setup]
(0x0100): Not using FAST.

*
Here is the ldap_child.log file...

*(Mon Apr 15 09:41:27 2013) [[sssd[ldap_child[18435]]]]
[ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18779]]]]
[ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/
xx.la3.4over.com at 4OVER.COM]
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18779]]]]
[ldap_child_get_tgt_sync] (0x0100): Using keytab [default]
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18779]]]]
[ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18779]]]]
[ldap_child_get_tgt_sync] (0x0010): Failed to init credentials: Client
'host/xx.la3.4over.com at 4OVER.COM' not found in Kerberos database
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18779]]]] [main] (0x0020):
ldap_child_get_tgt_sync failed.
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18780]]]]
[ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/
xx.la3.4over.com at 4OVER.COM]
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18780]]]]
[ldap_child_get_tgt_sync] (0x0100): Using keytab [default]
(Mon Apr 15 09:43:10 2013) [[sssd[ldap_child[18780]]]]
[ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals
(Mon Apr 15 09:43:55 2013) [[sssd[ldap_child[18884]]]]
[ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/
xx.la3.4over.com at 4OVER.COM]
(Mon Apr 15 09:43:55 2013) [[sssd[ldap_child[18884]]]]
[ldap_child_get_tgt_sync] (0x0100): Using keytab [default]
(Mon Apr 15 09:43:55 2013) [[sssd[ldap_child[18884]]]]
[ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals
(Mon Apr 15 09:44:50 2013) [[sssd[ldap_child[19099]]]]
[ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/
xx.la3.4over.com at 4OVER.COM]
(Mon Apr 15 09:44:50 2013) [[sssd[ldap_child[19099]]]]
[ldap_child_get_tgt_sync] (0x0100): Using keytab [default]
(Mon Apr 15 09:44:50 2013) [[sssd[ldap_child[19099]]]]
[ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals
(Mon Apr 15 09:59:46 2013) [[sssd[ldap_child[20244]]]]
[ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/
xx.la3.4over.com at 4OVER.COM]
(Mon Apr 15 09:59:46 2013) [[sssd[ldap_child[20244]]]]
[ldap_child_get_tgt_sync] (0x0100): Using keytab [default]
(Mon Apr 15 09:59:46 2013) [[sssd[ldap_child[20244]]]]
[ldap_child_get_tgt_sync] (0x0100): Will canonicalize principals
(Mon Apr 15 09:59:46 2013) [[sssd[ldap_child[20244]]]]
[ldap_child_get_tgt_sync] (0x0010): Failed to init credentials: Client
'host/xx.la3.4over.com at 4OVER.COM' not found in Kerberos database
(Mon Apr 15 09:59:46 2013) [[sssd[ldap_child[20244]]]] [main] (0x0020):
ldap_child_get_tgt_sync failed.
(Mon Apr 15 09:59:46 2013) [[sssd[ldap_child[20245]]]]
[ldap_child_get_tgt_sync] (0x0100): Principal name is: [host/
xx.la3.4over.com at 4OVER.COM]

*
Now restarting the SSSD daemon alleviates the issue - but the problem still
creeps up after a day or two.

I'm running 2.1.90.rc1 on CentOS 6.3 - I have 3 IPA servers that are
multimaster.

--Christian
**
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20130415/e7dfb627/attachment.htm>