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

Mon Apr 15 19:01:43 UTC 2013

We are running 1.9.2

Looks like 3.0 is available for my build of CentOS ~ Any suggestions on how
to proceed to updating? Is Multimaster replication "sustained" during
updating?

Thank you,

Christian Hernandez
1225 Los Angeles Street
Glendale, CA 91204
Phone: 877-782-2737 ext. 4566
Fax: 818-265-3152
christianh at 4over.com <mailto:christianh at 4over.com>
www.4over.com <http://www.4over.com>

On Mon, Apr 15, 2013 at 11:29 AM, Rob Crittenden <rcritten at redhat.com>wrote:

> 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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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 <xx.la3.4over.com at 4OVER.COM> <mailto:
>> xx.la3.4over.com@**4OVER.COM <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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20130415/7317fe37/attachment.htm>