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

Mon Apr 15 18:29:18 UTC 2013

Christian Hernandez wrote:
> 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 <http://4OVER.COM>]]]
> [be_pam_handler] (0x0100): Got request with the following data
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): command: PAM_ACCT_MGMT
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): domain: 4OVER.COM <http://4OVER.COM>
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): user: tradeftp
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): service: vsftpd
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): tty: ftp
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): ruser: tradeftp
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): rhost: mammoth.4over.com
> <http://mammoth.4over.com>
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): authtok type: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): authtok size: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): newauthtok type: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): newauthtok size: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): priv: 1
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): cli_pid: 17841
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://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 <http://4OVER.COM>]]]
> [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, <NULL>)
> [Success]
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [be_pam_handler_callback] (0x0100): Backend returned: (0, 0, Success)
> [Success]
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [be_pam_handler_callback] (0x0100): Sending result [0][4OVER.COM
> <http://4OVER.COM>]
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [be_pam_handler_callback] (0x0100): Sent result [0][4OVER.COM
> <http://4OVER.COM>]
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [be_pam_handler] (0x0100): Got request with the following data
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): command: PAM_SETCRED
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): domain: 4OVER.COM <http://4OVER.COM>
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): user: tradeftp
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): service: vsftpd
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): tty: ftp
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): ruser: tradeftp
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): rhost: mammoth.4over.com
> <http://mammoth.4over.com>
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): authtok type: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): authtok size: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): newauthtok type: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): newauthtok size: 0
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): priv: 1
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [pam_print_data] (0x0100): cli_pid: 17841
> (Mon Apr 15 09:36:59 2013) [sssd[be[4OVER.COM <http://4OVER.COM>]]]
> [be_pam_handler] (0x0100): Sending result [0][4OVER.COM <http://4OVER.COM>]
> (Mon Apr 15 09:37:00 2013) [sssd[be[4OVER.COM <http://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 <http://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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto: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.

A pre-release of IPA... You might consider upgrading to the latest, at 
least an official 2.x release for RHEL. I don't believe the version is 
related to these problems though.

What version of sssd is this?

There are some odd errors in ldap_child.log but it seems to cover a 
later period than the other logs (not being able to bind using its 
keytab is a bad thing).

I think what you'll want to do, and this may be relatively tough, is try 
to correlate these failures with the 389-ds access log and the KDC logs 
to see if there are equivalent failures at around the same times.

rob