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 [trade...@4over.com <mailto:trade...@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 [trade...@4over.com <mailto:trade...@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 [trade...@4over.com <mailto:trade...@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 [trade...@4over.com <mailto:trade...@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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....@4over.com <mailto:xx.la3.4over....@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

_______________________________________________
Freeipa-users mailing list
Freeipa-users@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-users

Reply via email to